Horovod Timeline - How to get the duration of operations? #3512

Snoeprol · 2022-04-20T11:24:50Z

Snoeprol
Apr 20, 2022

So I'm using the --timeline-filename flag to get a timeline.

An example line (using 4 workers):

{"ph": "B", "name": "NEGOTIATE_ALLREDUCE", "ts": 562372176, "pid": 2955},
{"ph": "X", "name": "3", "ts": 562372179, "pid": 2955, "dur": 0},
{"ph": "X", "name": "0", "ts": 562377251, "pid": 2955, "dur": 0},
{"ph": "X", "name": "2", "ts": 562377304, "pid": 2955, "dur": 0},
{"ph": "X", "name": "1", "ts": 562378267, "pid": 2955, "dur": 0},
{"ph": "E", "ts": 562378269, "pid": 2955},
{"ph": "B", "name": "ALLREDUCE", "ts": 562378316, "pid": 2955},
{"ph": "B", "name": "WAIT_FOR_DATA", "ts": 562378318, "pid": 2955},
{"ph": "E", "ts": 562378328, "pid": 2955},
{"ph": "B", "name": "WAIT_FOR_OTHER_TENSOR_DATA", "ts": 562378329, "pid": 2955},
{"ph": "E", "ts": 562378390, "pid": 2955},
{"ph": "B", "name": "QUEUE", "ts": 562379234, "pid": 2955},
{"ph": "E", "ts": 562379238, "pid": 2955},
{"ph": "B", "name": "NCCL_ALLREDUCE", "ts": 562379240, "pid": 2955},
{"ph": "E", "ts": 562379243, "pid": 2955},
{"ph": "E", "ts": 562379252, "pid": 2955, "args": {"dtype": "int32", "shape": "[959888]"}},
{"name": "process_name", "ph": "M", "pid": 2956, "args": {"name": "allgather.noname.2966"}},
{"name": "process_sort_index", "ph": "M", "pid": 2956, "args": {"sort_index": 2956}},

When I display this process in Chrome it nicely shows how long the ALLREDUCE operation took, but there is no information in the json file. Is this just done looking at the ts entry of the WAIT_FOR_DATA, and NCCL_ALLREDUCE operations?

Because in this case that would not give the same result?

Any clues on this? I am trying to obtain the total communication time in the process.

Thanks,

Mario

Answered by maxhgerlach

Apr 20, 2022

"ph" (phase) can be, among others, "B" (begin) and "E" (end). "ts" is the associated timestamp (μsec, I believe). Multiple duration events can be nested.

{"ph": "B", "name": "NEGOTIATE_ALLREDUCE", "ts": 562372176, "pid": 2955},
{"ph": "X", "name": "3", "ts": 562372179, "pid": 2955, "dur": 0},
{"ph": "X", "name": "0", "ts": 562377251, "pid": 2955, "dur": 0},
{"ph": "X", "name": "2", "ts": 562377304, "pid": 2955, "dur": 0},
{"ph": "X", "name": "1", "ts": 562378267, "pid": 2955, "dur": 0},
{"ph": "E", "ts": 562378269, "pid": 2955},

Here you have the beginning and ending time stamps of the "NEGOTIATE_ALLREDUCE" stage. The "X" events are markers when the four ranks signaled to be ready IIRC.

T…

View full answer

maxhgerlach · 2022-04-20T14:39:20Z

maxhgerlach
Apr 20, 2022
Collaborator

"ph" (phase) can be, among others, "B" (begin) and "E" (end). "ts" is the associated timestamp (μsec, I believe). Multiple duration events can be nested.

{"ph": "B", "name": "NEGOTIATE_ALLREDUCE", "ts": 562372176, "pid": 2955},
{"ph": "X", "name": "3", "ts": 562372179, "pid": 2955, "dur": 0},
{"ph": "X", "name": "0", "ts": 562377251, "pid": 2955, "dur": 0},
{"ph": "X", "name": "2", "ts": 562377304, "pid": 2955, "dur": 0},
{"ph": "X", "name": "1", "ts": 562378267, "pid": 2955, "dur": 0},
{"ph": "E", "ts": 562378269, "pid": 2955},

Here you have the beginning and ending time stamps of the "NEGOTIATE_ALLREDUCE" stage. The "X" events are markers when the four ranks signaled to be ready IIRC.

This Google Doc seems to describe the data format quite nicely: https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Horovod Timeline - How to get the duration of operations? #3512

Uh oh!

{{title}}

Uh oh!

Replies: 1 comment

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Select a reply

Uh oh!

Horovod Timeline - How to get the duration of operations? #3512

Uh oh!

Snoeprol Apr 20, 2022

Replies: 1 comment

Uh oh!

Uh oh!

maxhgerlach Apr 20, 2022 Collaborator

Snoeprol
Apr 20, 2022

maxhgerlach
Apr 20, 2022
Collaborator