rocm-systems/ext-profiler/example

NCCL Example Profiler Plugin Usage

This page describes how to use the NCCL example profiler plugin

Overview

The example profiler plugin implements the NCCL profiler plugin API introduced in NCCL v2.23. The API defines a set of events and data structures that NCCL uses to share event information with profiler plugins. The user can control what events are instrumented by NCCL and when traces collected by the profiler should be dumped through environment variables, as described in the rest of the document. The user can also control other profiler parameters that alter its behavior. For example, users can change the size of the event window the profiler keeps track of.

Building the profiler plugin

To build the example plugin shipped as part of NCCL, just type make.

Using the profiler plugin

1. Add the directory of this profiler plugin to your LD_LIBRARY_PATH or set the NCCL_PROFILER_PLUGIN, as documented in ext-profiler/README.md.

2. Set NCCL_PROFILE_EVENT_MASK bitmask to specify the NCCL events you want to instrument. By default, all collectives and send/recv operations will be traced. For more details about the event representation used by the profiler refer to ext-profiler/README.md.

   As an example, setting:

   NCCL_PROFILE_EVENT_MASK to 256 (ncclProfileGroupApi) | 2 (ncclProfileColl) | 8 (ncclProfileProxyOp)

   enables the profiling of the group API, the collective and the proxy op events. The same events can be expressed more concisely by setting NCCL_PROFILE_EVENT_MASK to 8 (ncclProfileProxyOp). Indeed, in NCCL all the events above (in the event hierarchy) the one requested are also captured. The advantage is that the profiler can easily correlate events that belong to the same NCCL operation and present them accordingly. Setting NCCL_PROFILE_EVENT_MASK to 4095 enables all events supported by the v5 profiler.

3. Set NCCL_PROFILE_DUMP_FILE to the name of the dump file for the collected traces. A file named ${NCCL_PROFILE_DUMP_FILE}-hostname-tid.txt is created. Profiler traces are saved using the chrome event format (more precisely, using asynchronous events).

4. If you set the dump file variable, type chrome://tracing on your chromium browser search bar and open the created dump file to visualize the traces.

Changing the profiler memory pool sizes

The example profiler uses separate memory pools for different types of events. The size of these memory pools (i.e., the # events) determines the number of events that the profiler can keep track of at the same time. When NCCL requests a new event (e.g., collective event) to profile a ncclAllReduce operation, by calling startEvent, the profiler searches in the collective pool for a free event. If it finds one, it marks it as in use and returns the handle to NCCL. If the pool is completely used the profiler returns NULL to NCCL and ignores all the following NCCL profiler calls for the NULL event handle. When the ncclAllReduce has been processed, NCCL calls stopEvent with the previosly returned event handle. The profiler has a total of 5 memory pools.

The group, collective and p2p pools contain objects for the corresponding events. The ProxyCtrl pool contains objects for ProxyCtrl events and the ProxyDetach pool contains objects for ProxyOp events generated by remote proxies. A list of pools and their size is reported below:

• NCCL_PROFILE_GROUP_API_POOL_SIZE (256)
• NCCL_PROFILE_COLL_API_POOL_SIZE (256)
• NCCL_PROFILE_P2P_API_POOL_SIZE (256)
• NCCL_PROFILE_KERNEL_LAUNCH_POOL_SIZE (256)
• NCCL_PROFILE_COLL_POOL_SIZE (256)
• NCCL_PROFILE_P2P_POOL_SIZE (256)
• NCCL_PROFILE_PROXY_CTRL_POOL_SIZE (16)
• NCCL_PROFILE_PROXY_DETACH_POOL_SIZE (256)

Remote proxy operations are generated when PXN is in use. Refer to this article for more information about PXN and how it works: https://developer.nvidia.com/blog/doubling-all2all-performance-with-nvidia-collective-communication-library-2-12/

Reported events

The example profiler generates traces using the json format. An example of trace is reported below:

[
{"name": "Group API", "cat": "GROUP_API", "ph": "b", "id": 0, "pid": 225798, "tid": 1, "ts": 3433.595001, "args": {"groupApiId": 0, "groupDepth":1}},
{"name": "KernelLaunch", "cat": "KERNEL_LAUNCH", "ph": "b", "id": 0, "pid": 225798, "tid": 1, "ts": 0.000000, "args": {"groupId": 0, "Stream": 0x5020000567d0}},
{"name": "KernelLaunch", "cat": "KERNEL_LAUNCH", "ph": "e", "id": 0, "pid": 225798, "tid": 1, "ts": 111991.558990},
{"name": "AllReduce", "cat": "COLL_API", "ph": "b", "id": 0, "pid": 225798, "tid": 1, "ts": 0.000000, "args": {"count": 262144, "datatype": ncclFloat32, "root": 0, "GraphCaptured":0, "Stream": 0x5020000567d0}},
{"name": "AllReduce", "cat": "COLL", "ph": "b", "id": 0, "pid": 225798, "tid": 1, "ts": 111994.477997, "args": {"SeqNum": 0, "CommHash": 1493613951195738943, "Rank": 0, "Count": 262144, "Datatype": "ncclFloat32", "Algorithm": "RING", "Protocol": "SIMPLE", "nChannels": 2}},
{"name": "KernelCh", "cat": "GPU", "ph": "b", "id": 0, "pid": 225798, "tid": 1, "ts": 119711.888000, "args": {"Channel": 0, "StartGpuClk": 1756135989724672000, "StopGpuClk": 1756135989732831232}},
{"name": "ScheduleRecv", "cat": "PROXY", "ph": "b", "id": 0, "pid": 225798, "tid": 1, "ts": 119652.709991, "args": {"Channel": 0, "Peer": 1, "Steps": 4, "ChunkSize": 4194304, "transSize": 524288}},
{"name": "ScheduleRecv", "cat": "PROXY", "ph": "e", "id": 0, "pid": 225798, "tid": 1, "ts": 119686.300995},
{"name": "ProgressRecv", "cat": "PROXY", "ph": "b", "id": 0, "pid": 225798, "tid": 1, "ts": 119686.300995, "args": {"Channel": 0, "Peer": 1, "Steps": 4, "ChunkSize": 4194304, "transSize": 524288}},
{“name": "RecvWait", "cat": "NET", "ph": "b", "id": 0, "pid": 225798, "tid": 1, "ts": 119707.677979, "args": {"Step": 0}},
{"name": "RecvWait", "cat": "NET", "ph": "e", "id": 0, "pid": 225798, "tid": 1, "ts": 119807.691986},
{"name": "RecvFlushWait", "cat": "NET", "ph": "b", "id": 0, "pid": 225798, "tid": 1, "ts": 119807.691986, "args": {"Step": 0}},
{"name": "RecvFlushWait", "cat": "NET", "ph": "e", "id": 0, "pid": 225798, "tid": 1, "ts": 119867.338989},
{"name": "RecvGpuWait", "cat": "NET", "ph": "b", "id": 0, "pid": 225798, "tid": 1, "ts": 119867.338989, "args": {"Step": 0}},
{"name": "RecvGpuWait", "cat": "NET", "ph": "e", "id": 0, "pid": 225798, "tid": 1, "ts": 120120.983002},
{"name": "RecvWait", "cat": "NET", "ph": "b", "id": 1, "pid": 225798, "tid": 1, "ts": 119733.647980, "args": {"Step": 1}},
{"name": "RecvWait", "cat": "NET", "ph": "e", "id": 1, "pid": 225798, "tid": 1, "ts": 119844.401001},
{"name": "RecvFlushWait", "cat": "NET", "ph": "b", "id": 1, "pid": 225798, "tid": 1, "ts": 119844.401001, "args": {"Step": 1}},
{"name": "RecvFlushWait", "cat": "NET", "ph": "e", "id": 1, "pid": 225798, "tid": 1, "ts": 119890.567993},
{"name": "RecvGpuWait", "cat": "NET", "ph": "b", "id": 1, "pid": 225798, "tid": 1, "ts": 119890.567993, "args": {"Step": 1}},
{"name": "RecvGpuWait", "cat": "NET", "ph": "e", "id": 1, "pid": 225798, "tid": 1, "ts": 120121.129974},
{"name": "RecvWait", "cat": "NET", "ph": "b", "id": 2, "pid": 225798, "tid": 1, "ts": 119753.023987, "args": {"Step": 2}},
{"name": "RecvWait", "cat": "NET", "ph": "e", "id": 2, "pid": 225798, "tid": 1, "ts": 120038.847992},
{"name": "RecvFlushWait", "cat": "NET", "ph": "b", "id": 2, "pid": 225798, "tid": 1, "ts": 120038.847992, "args": {"Step": 2}},
{"name": "RecvFlushWait", "cat": "NET", "ph": "e", "id": 2, "pid": 225798, "tid": 1, "ts": 120085.685974},
{"name": "RecvGpuWait", "cat": "NET", "ph": "b", "id": 2, "pid": 225798, "tid": 1, "ts": 120085.685974, "args": {"Step": 2}},
{"name": "RecvGpuWait", "cat": "NET", "ph": "e", "id": 2, "pid": 225798, "tid": 1, "ts": 120121.244995},
{"name": "RecvWait", "cat": "NET", "ph": "b", "id": 3, "pid": 225798, "tid": 1, "ts": 119772.510986, "args": {"Step": 3}},
{"name": "RecvWait", "cat": "NET", "ph": "e", "id": 3, "pid": 225798, "tid": 1, "ts": 120062.944977},
{"name": "RecvFlushWait", "cat": "NET", "ph": "b", "id": 3, "pid": 225798, "tid": 1, "ts": 120062.944977, "args": {"Step": 3}},
{"name": "RecvFlushWait", "cat": "NET", "ph": "e", "id": 3, "pid": 225798, "tid": 1, "ts": 120101.089996},
{"name": "RecvGpuWait", "cat": "NET", "ph": "b", "id": 3, "pid": 225798, "tid": 1, "ts": 120101.089996, "args": {"Step": 3}},
{"name": "RecvGpuWait", "cat": "NET", "ph": "e", "id": 3, "pid": 225798, "tid": 1, "ts": 120165.115997},
{"name": "ProgressRecv", "cat": "PROXY", "ph": "e", "id": 0, "pid": 225798, "tid": 1, "ts": 120165.356995},
{"name": "ScheduleSend", "cat": "PROXY", "ph": "b", "id": 1, "pid": 225798, "tid": 1, "ts": 119656.950989, "args": {"Channel": 0, "Peer": 1, "Steps": 4, "ChunkSize": 4194304, "transSize": 524288}},
{"name": "ScheduleSend", "cat": "PROXY", "ph": "e", "id": 1, "pid": 225798, "tid": 1, "ts": 119709.078979},
{"name": "ProgressSend", "cat": "PROXY", "ph": "b", "id": 1, "pid": 225798, "tid": 1, "ts": 119709.078979, "args": {"Channel": 0, "Peer": 1, "Steps": 4, "ChunkSize": 4194304, "transSize": 524288}},
{"name": "SendGpuWait", "cat": "NET", "ph": "b", "id": 4, "pid": 225798, "tid": 1, "ts": 119710.632996, "args": {"Step": 0}},
{"name": "SendGpuWait", "cat": "NET", "ph": "e", "id": 4, "pid": 225798, "tid": 1, "ts": 119808.636993},
{"name": "SendPeerWait", "cat": "NET", "ph": "b", "id": 4, "pid": 225798, "tid": 1, "ts": 119808.636993, "args": {"Step": 0}},
{"name": "SendPeerWait", "cat": "NET", "ph": "e", "id": 4, "pid": 225798, "tid": 1, "ts": 119818.972992},
 ... [ trace truncated for brevity ]
{"name": "AllReduce", "cat": "COLL", "ph": "e", "id": 17, "pid": 225798, "tid": 1, "ts": 170633.535980},
{"name": "AllReduce", "cat": "COLL_API", "ph": "e", "id": 17, "pid": 225798, "tid": 1, "ts": 170582.923981},
{"name": "Group API", "cat": "GROUP_API", "ph": "e", "id": 17, "pid": 225798, "tid": 1, "ts": 170637.582001},
{}]

Details about the fields used in the trace can be found at this link: https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview?tab=t.0#heading=h.yr4qxyxotyw

The trace above is obtained by running a ncclAllReduce operation on 2 GPUs, communicating with each other through the network interface. The Group event encloses all traces that are related to the single ncclAllReduce call. (Note that for single collective invocations, where there are no explicit group calls, NCCL creates a group with only one collective and this is what is presented in the traces above).

The AllReduce event encloses traces for the proxy operation associated to the ncclAllReduce operation. The args field in the traces contains NCCL specific information (aside from the chrome trace event format).

AllReduce trace

The AllReduce entry presents information about the ncclAllReduce operation. It contains the following info in the args field:

• seqNum : sequential number of the collective in the communicator (every collective type has its own sequence number in the communicator)
• commHash : communicator unique identifier
• rank : NCCL rank for the ncclAllReduce
• datatype : NCCL datatype
• algorithm : algorithm used to process the ncclAllReduce
• protocol : protocol used to process the ncclAllReduce
• nChannels : Number of channels used to process the ncclAllReduce

If the proxy events are not active (e.g., the ncclAllReduce is intranode) the end timestamp will match the time consumed by the CPU to launch the collective. For more details refer to ext-profiler/README.md, section Profiling of collective and p2p operations.

The Proxy send trace gives a summary of the proxy progress thread activity for the channel. If more details are needed, these can be obtained by enabling the proxy step event (ncclProfileProxyStep). In which case the trace entries below are also reported by the profiler.

Proxy SendGpuWait

Presents, for every network step, the time the CPU proxy spends waiting for the GPU to provide the data in the staging buffer.

Proxy SendWait

Presents, for every network step, the time the CPU proxy spends waiting for the isend to complete

Proxy RecvWait

Presents, for every network step, the time the CPU proxy spends waiting for a posted irecv to complete

Proxy RecvFlushWait

Presents, for every network step, the time the CPU proxy spends waitng for the recv data to be flushed to the GPU

Proxy RecvGpuWait

Presents, for every network step, the time the CPU proxy spends waiting for the GPU to consume the recv data