Tracing and Profiling

Warning: We assume that you are familiar with deploying, configuring and using RADICAL-Pilot, for example by taking the getting started introduction tutorial.

Tracing may help user to gather information about the behavior of RADICAL-Pilot (RP) and of their application’s tasks during or after execution. RP uses dedicated files to log tracing information. Those files end with the *.prof extension and are stored inside sandboxes. For details about RP’s sandboxes, see Generated Output in our Getting Started tutorial.

In RP lingo, a trace is a collection of timestamps, where each time stamp is associated to an event that, in turn, originates within a specific RP’s component in a given context. That is a lot of information. In order to organize that information, we created an event model, a state model and a dedicated format for each record in a trace.

You must distinguish between tracing the behavior of RP from tracing the behavior of the tasks of your application. RP does not trace the inner behavior of a task. For RP, each task is a black box: once launched, the behavior of a task is unknown to RP. This is by design and helps to maintain a rigid separation of concerns between RP and each task, enabling the concurrent execution of heterogeneous tasks. If you need to trace the behavior of your tasks, you can use tools like TAU or other tracers/profilers.

Event and state models

RP’s event model defines the event triggered by each RP’s component, alongside its description and *.prof file where it is recorded. Note that, as reported in the event model’s table, not all the events are guaranteed to be fired by each configuration of RP. In order to use RP’s tracing capabilities to monitor and analyze the execution of your application, you will have to study the description of each event, understand what information gives you about either RP or your tasks, and then name an informed decision on which events fit your purpose.

Understanding all the above requires a careful consideration of RP’s architecture and an understanding of where and when each component executes. Sounds too complicated? It is. Go and see how to use RADICAL-Analytics to simplify tracing and profiling, albeit only after your application has completed its execution.

In RP’s lingo, a state is a special type of event. States have two properties that are relevant to tracing:

  1. Each state is guaranteed to fire in every possible configuration of RP, i.e., independent on the platform on which it executes, the number and types of resources, the specific virtual environment it uses for its Agent and the other myriad of possible configurations of RP.

  2. States are guaranteed to always fire in a precise sequence, i.e., each state is part of a well-defined, immutable sequence.

When tracing your application, states trade off granularity for reliability. As such, they are also easier to use as they require a less granular and specific understanding of RP. To see the list of states, ordered in their guaranteed sequence, see RP’s state model.

Record format

Each *.prof file uses the following format:

time,event,comp,thread,uid,state,msg

Where:

  • time = (mandatory) timestamp expressed in Unix Time (epoch)

  • event = (mandatory) the name of the timestamped event

  • comp = (optionl) the name of the component that triggered the event

  • thread = (mandatory) the ID of the thread in which the event was triggered with comp

  • uid = (mandatory) the ID of the entity to which that event belongs (e.g., task or pilot)

  • state = (optional) the name given to the event when it is also a state, i.e., guaranteed to be triggered in every configuration of RP

  • msg = (optional) an arbitrary message associated to that event.

For example, here is the record of the launch_start event for a task:

1684787127.2228520,launch_start,,MainThread,task.000000,AGENT_EXECUTING,

As you will see later in this tutorial, you can use launch_start to monitor when a task is/was launched to be executed. Here is another example, this time for the schedule_ok event triggered by RP’s Agent Scheduler:

1684787127.1614347,schedule_ok,agent_scheduling.0000,Thread-1 (_worker_thread),task.000000,,

First note that this event is not a state, e.g., it would not fire in a configuration of RP where the scheduler is bypassed (a corner case as, for every practical purpose, this event will also fire!). As described in the event model, schedule_ok indicates the time at which the scheduler’s search for task resources succeeded. Tracing this event for each task would give you the time series of when all your tasks were/are scheduled by RP for execution.

Note: Order matters! States are guaranteed to be triggered always in the same order while only a subset of events have a partial order within each module. Consider that partial order when consulting event model.

RADICAL Analytics

Parsing and filtering the *.proffiles requires a solid understanding of:

  1. RP’s event/state model in order to select only the information you actually need;

  2. the format in which the information is encoded within the *.prof file;

  3. in which file or files RP recorded the information you need;

  4. bash commands/scripts to parse and filter those files.

That is both difficult and cumbersome.

In order to facilitate using RP traces to profile the execution of your application, we created RADICAL Analytics (RA). Please see the linked documentation and consider using RA whenever you need postmortem profiling. In the following, we discuss how you can perform some task-related tracing at runtime or postmortem, i.e., while RP is executing your application or once it finished. This is useful while developing your application and/or for spot-checks while executing a large run. For production profiling, you should use RA.

Tracing at runtime

In a real-life scenario, you will:

  1. Start the execution of your application on a supported HPC platform;

  2. while the application is running, execute shell commands to parse and filter across multiple *.prof files.

The format of this tutorial does not allow for concurrently running both your application and the shell commands you need to spot-check the behavior of your tasks. Thus, we first run a sample application and then show some useful shell commands.

Warning: In real-life scenarios, your shell commands will operate on multiple small files created on a filesystem shared by all the compute nodes of the HPC platform. Even with just as little as a few hundreds tasks, your shell commands could deteriorate the performance of the shared file systems. You should exercise extreme caution as the whole HPC machine could grind to a halt. That would affect all the users of the machine and make the system administrators very unhappy; ask as we know…

Here we:

  1. Use the RADICAL_PROFILE environment variable to enable RP tracing;

  2. run a condensed version of the application we used for the Getting Started.

Warning: By default, RP sets RADICAL_PROFILE to TRUE. When set to FALSE, RP will not create the *.prof files.

[1]:

%env RADICAL_PROFILE=True
%env RADICAL_REPORT_ANIME=False

import os
import random
import radical.pilot as rp

session = rp.Session()
pmgr = rp.PilotManager(session=session)

pd_init = {'resource'     : 'local.localhost',
           'runtime'      : 30,  # pilot max runtime in minutes
           'cores'        : 4,
           'gpus'         : 0,
           'exit_on_error': False}

n = 10
tds = list()

for i in range(n):

    td = rp.TaskDescription()
    td.executable     = 'radical-pilot-hello.sh'
    td.arguments      = [random.randint(1, 10)]
    td.ranks          =  1
    td.cores_per_rank =  random.randint(1, 2)
    tds.append(td)

pdesc = rp.PilotDescription(pd_init)
pilot = pmgr.submit_pilots(pdesc)

tmgr = rp.TaskManager(session=session)
tmgr.add_pilots(pilot)
tmgr.submit_tasks(tds)
tmgr.wait_tasks()

session.close()

env: RADICAL_PROFILE=True
env: RADICAL_REPORT_ANIME=False

Task state

Typically, you will want to know in which state your tasks are during runtime. Did my task start to execute? Here is an example of how you could answer to that question using bash commands and RP’s traces:

First, we get the name of the session you are running/have just run. We save it to a Python variable, and we also export it to a shell variable so to be able to access it both within this notebook and from the shell commands.

[2]:

%env SESSION_ID=$session.uid

env: SESSION_ID=rp.session.122de958-fd45-11ee-95fc-0242ac110002

Second, for each task, we parse its *.prof file, filtering for the event app_start. That will tell us whether and when each task started to execute.

Note: How do you know that you need the event app_start? You read the definition of each event in the RP’s event model.

Note: How do you know that the event app_start is recorded in the file task.*.prof? You read in the RP’s event model in which file the app_start event is written.

Here is the list of events recorded for task.000000.

[3]:

!cat ~/radical.pilot.sandbox/$SESSION_ID/pilot.0000/task.000000/task.000000.prof

1713418384.2353060,launch_start,,MainThread,task.000000,AGENT_EXECUTING,
1713418384.2384160,launch_pre,,MainThread,task.000000,AGENT_EXECUTING,
1713418384.2402060,launch_submit,,MainThread,task.000000,AGENT_EXECUTING,
1713418384.2436061,exec_start,,MainThread,task.000000,AGENT_EXECUTING,
1713418384.2467799,exec_pre,,MainThread,task.000000,AGENT_EXECUTING,
1713418384.2498519,rank_start,,MainThread,task.000000,AGENT_EXECUTING,
1713418384.2597849,app_start,,MainThread,task.000000,AGENT_EXECUTING,
1713418392.3336689,app_stop,,MainThread,task.000000,AGENT_EXECUTING,
1713418392.3351820,rank_stop,,MainThread,task.000000,AGENT_EXECUTING,RP_EXEC_PID=19998:RP_RANK_PID=20009
1713418392.3366570,exec_post,,MainThread,task.000000,AGENT_EXECUTING,
1713418392.3378670,exec_stop,,MainThread,task.000000,AGENT_EXECUTING,
1713418392.3396950,launch_collect,,MainThread,task.000000,AGENT_EXECUTING,RP_LAUNCH_PID=19990
1713418392.3409081,launch_post,,MainThread,task.000000,AGENT_EXECUTING,
1713418392.3425319,launch_stop,,MainThread,task.000000,AGENT_EXECUTING,

You can filter only the information you care about from each list of traces. Further, you may want to convert each timestamp from Unix Time (epoch) to a human-readable date/time.

[4]:

!for trace in `find ~/radical.pilot.sandbox/$SESSION_ID/pilot.0000/ -type f -name  "task.*.prof"`; do \
    time_stamp=`grep 'app_start' $trace`      ; \
    IFS=, read -a fields <<<"$time_stamp"     ; \
    start_time=`date -d  @${fields[0]} +'%c'` ; \
    echo ${fields[4]}: $start_time            ; \
done

/usr/bin/sh: 1: Syntax error: redirection unexpected

We also want to know whether and when each task finished.

[5]:

!for trace in `find ~/radical.pilot.sandbox/$SESSION_ID/pilot.0000/ -type f -name  "task.*.prof"`; do \
    start=`grep 'app_start' $trace`; stop=`grep 'app_stop' $trace`      ; \
    IFS=, read -a fields_start <<<"$start"                              ; \
    IFS=, read -a fields_stop <<<"$stop"                                ; \
    start_time=`date -d  @${fields_start[0]} +'%r'`                     ; \
    stop_time=`date -d  @${fields_stop[0]} +'%r'`                       ; \
    echo ${fields_start[4]} \-\> start: $start_time \| stop: $stop_time ; \
done

/usr/bin/sh: 1: Syntax error: redirection unexpected

In a shell environment, you could save the list of traces in a variable so to limit the amount of times we hit the shared filesystem of the HPC platform. Further, you could define a set of aliases and make those for commands more compact and easy to issue. At runtime you could use the watch command to “monitor” the progression of the tasks at regular intervals. In presence of large amount of files, you could avoid printing an unreadable list of files and just print aggregates of the number of files that have been done. Again, you should exercise extreme caution to avoid overloading the shared file system.

Tracing heterogeneous tasks

Concurrently, executing heterogeneous tasks on heterogeneous resources is RP’s most distinctive and useful capability. Thus, it is likely you will execute different types of tasks and that you may want to trace tasks based on their type. Looking at the examples above, you will notice that tasks are named as task.xxxxxx, giving no information about what actually was the type of executable of each task.

You can introduce arbitrary information about each task using the uid properties of the TaskDescription object. This will create an arbitrary UID for each task, in which you will be able to codify distinctive properties like, for example, simulation, analysis, machine_learning, etc. Once you do that, you will be able to parse and filter the task profiles looking for the UIDs you defined. Go ahead, try this out by download the container of this tutorial, executing it on your local machine via Docker and editing the code to introduce your own UIDs and create your own shell commands to trace their execution.