Log slow bulk and search task execution across various node interactions

Problem

If there are problems in the system occurring due to slow IO or Network on a particular node the rest of the nodes also get impacted waiting on the response. There is no easy way to know from logs if a particular node has gone slow, either while doing a live DEBUG or figuring out the root cause of the incident. The current slow logs serves into providing shard-level details on slow query or index. At present there is no way to know the coordinator view

Proposal

We can attach a listener to the TransportAction corresponding to bulk and search and log warning of the execution time of the bulk task eg shard bulk/primary/replication tasks if they take beyond a reasonable threshold with the below details.

From the below details we could atleast make out there is a slow replication action(time in queue + time spent in the replica indexing) on the problematic node. Since we know the task id and the parent id we should be able to get a break down of the entire bulk request.

Note since the replica action took longer the primary and the coordinator action will have a corresponding log line. Looking at all of them holistically we should be able to reason and pin point about the slow action

On Primary

[2021-06-17T01:19:48,596][WARN ][c.a.c.e.logger           ] [dcdce07c4314957e5cc0e43d5cd60511] Action [indices:data/write/bulk[s][p]] on node [dcdce07c4314957e5cc0e43d5cd60511], 
task id : [26786394294], parent task id : [26795282749] took [88s] longer than the threshold of [60]s

On Coordinator

[2021-06-17T01:19:48,596][WARN ][c.a.c.e.logger           ] [hecgeg07c4314957e5cc0e43d5cd22221] Action [indices:data/write/bulk[s]] on node [hecgeg07c4314957e5cc0e43d5cd22221], 
task id : [26795282749], parent task id : [28668306216] took [98s] longer than the threshold of [60]s

This way we know the time spent across layers also getting the N/W round trip delay between tasks

Start with the TransportAction entry points for bulk and search, then review how existing slow logs capture shard-level execution. Define how execution time and the threshold should be applied across coordinator, primary, and replica actions. Done means warning logs identify the action, node, task IDs, parent task ID, elapsed time, and threshold for slow executions.