rt-muse traces

[martinamaggio]

In this post I was asked to post some traces generated with rt-muse.

This trace is the result of the execution of the test taskset.json available in the repository (direct link to the test input).

Code: Select all

{
  "resources": 2,
  "shared": 50,
  "threads": {
    "thread1": {
      "priority": 10,
      "cpus": [0,1,2],
      "phases": {
        "c0": { "loops": 1000 },
        "l0": { "loops": 2000, "res": 0 },
        "s0": { "loops": 1000 },
        "l1": { "loops": 3000, "res": 1 },
        "m0": { "loops": 1000, "memory": 10 },
        "c1": { "loops": 5000 }
      },
      "analysis": { "supply": true, "statistical": true, 
                    "runmap": true, "migrations": true }
    },
    "thread2": {
      "priority": 10,
      "cpus": [0,1],
      "phases": {
        "c0": { "loops": 5000 },
        "m0": { "loops": 1000, "memory": 10 },
        "s0": { "loops": 5000 },
        "l0": { "loops": 10000, "res": 1 }
      }
    }
  },
  "global": {
    "default_policy": "SCHED_RR",
    "duration": 10,
    "analysis": { "supply": true }
  }
}

The test runs for 10 seconds and the task set consists of two threads scheduled with SCHED_RR.

The first thread has a job composed of 6 phases and can run on CPUs 0, 1 and 2 (set via the affinity mask of the thread).
For each job (repeated until the test ends) the first threads computes (phase starting with the letter c) 1000 mathematical operations, then locks (phase starting with the letter l) the mutex corresponding to resource 0 and computes for 2000 mathematical operations before unlocking it, then it uses a shared memory buffer (phase starting with the letter s) consisting of 50 double values created at the beginning of the execution, computing for 1000 mathematical operations and circularly writing the results in the buffer, then it does a second lock phase computing for 3000 mathematical operations and locking and releasing resource 1, then it allocates a buffer of memory consisting in 10 double values and computes for 1000 mathematical operations writing circularly on the buffer (phase starting with the letter m) and finally it computes again for 5000 mathematical operations.

This is encoded in the description of the job given in taskset.json:

Code: Select all

"phases": {
  "c0": { "loops": 1000 },
  "l0": { "loops": 2000, "res": 0 },
  "s0": { "loops": 1000 },
  "l1": { "loops": 3000, "res": 1 },
  "m0": { "loops": 1000, "memory": 10 },
  "c1": { "loops": 5000 }
}

The second thread computes, allocates memory, uses shared memory and locks resource 1. It can run on CPUs 0 and 1.

The attached file taskset.txt contains the trace as it is generated by the execution of the application and tracer.
With the command

Code: Select all

cat taskset.txt | grep tracing_mark_write

it is possible to see exactly the output produced by the mark in the application (when the threads begin their jobs). Since the output is extremely long, it is recommended to visualize it via cutting like

Code: Select all

head -n1000 taskset.txt | grep tracing_mark_write

The head command just above produces as output something that ends with this.

Code: Select all

<...>-3359  [002] 308616.223620: print:                tracing_mark_write: [1] begins job 150
<...>-3360  [000] 308616.223836: print:                tracing_mark_write: [2] begins job 150
<...>-3359  [002] 308616.223947: print:                tracing_mark_write: [1] begins job 151
<...>-3360  [000] 308616.224187: print:                tracing_mark_write: [2] begins job 151
<...>-3359  [002] 308616.224326: print:                tracing_mark_write: [1] begins job 152
<...>-3360  [000] 308616.224543: print:                tracing_mark_write: [2] begins job 152
<...>-3359  [002] 308616.224682: print:                tracing_mark_write: [1] begins job 153
<...>-3360  [000] 308616.224894: print:                tracing_mark_write: [2] begins job 153
<...>-3359  [002] 308616.225033: print:                tracing_mark_write: [1] begins job 154
<...>-3360  [000] 308616.225250: print:                tracing_mark_write: [2] begins job 154
<...>-3359  [002] 308616.225361: print:                tracing_mark_write: [1] begins job 155
<...>-3360  [000] 308616.225601: print:                tracing_mark_write: [2] begins job 155
<...>-3359  [002] 308616.225740: print:                tracing_mark_write: [1] begins job 156
<...>-3360  [000] 308616.225957: print:                tracing_mark_write: [2] begins job 156
<...>-3359  [002] 308616.226096: print:                tracing_mark_write: [1] begins job 157
<...>-3360  [000] 308616.226308: print:                tracing_mark_write: [2] begins job 157
<...>-3359  [002] 308616.226447: print:                tracing_mark_write: [1] begins job 158
<...>-3360  [000] 308616.226664: print:                tracing_mark_write: [2] begins job 158
<...>-3359  [002] 308616.226775: print:                tracing_mark_write: [1] begins job 159

where the first number in square brackets represents the CPU in which the line is executed, the subsequent one the timestamp, the second number in square brackets (after tracing_mark_write:) is the thread ID (thread 0 is the creator, the others are numbered from 1 on), and the final number is the job index.

To obtain the migrations occurred, one can simply do

Code: Select all

head -n1000 taskset.txt | grep sched_migrate_task

but since we log all the migrations happening in the system, this does not give as output only what produced at the application level. With the more precise

Code: Select all

head -n1000 taskset.txt | grep sched_migrate_task | grep application

it is possible to obtain the migrations that the application has experienced.

Code: Select all

<...>-3358  [000] 308615.136218: sched_migrate_task:   comm=application pid=3358 prio=120 orig_cpu=0 dest_cpu=0
<...>-3358  [000] 308615.136230: sched_migrate_task:   comm=application pid=3359 prio=120 orig_cpu=0 dest_cpu=3
<...>-30    [003] 308615.136265: sched_migrate_task:   comm=application pid=3359 prio=120 orig_cpu=3 dest_cpu=0
<...>-3357  [002] 308615.136279: sched_migrate_task:   comm=application pid=3359 prio=120 orig_cpu=0 dest_cpu=2
<...>-3358  [000] 308615.136283: sched_migrate_task:   comm=application pid=3358 prio=120 orig_cpu=0 dest_cpu=0
<...>-3358  [000] 308615.136292: sched_migrate_task:   comm=application pid=3360 prio=120 orig_cpu=0 dest_cpu=1
<...>-3354  [003] 308615.136304: sched_migrate_task:   comm=application pid=3360 prio=120 orig_cpu=1 dest_cpu=3
<...>-30    [003] 308615.136319: sched_migrate_task:   comm=application pid=3360 prio=120 orig_cpu=3 dest_cpu=0

The PID number of each thread corresponds to the number after the initial part of each line "<...>-" in the trace. The migration event can be generated by different threads (in this case, by 30, 3357, 3358...) and is recorded associated with its generator. Origin and destination CPU are also shown.

As a final note, in the tool we post process the traces and we obtain different and more compact representations for the same thing. For more details, visit the tool repository.

[Sophie Quinton]

Thanks for the detailed answer! After a short glimpse at the files, it seems to me that the only events that you trace are the beginning of a job (when a job actually starts executing) and task migrations. Am I correct? What about other events like preemptions, activations, terminations?

Best,
Sophie

[martinamaggio]

Thanks for the detailed answer! After a short glimpse at the files, it seems to me that the only events that you trace are the beginning of a job (when a job actually starts executing) and task migrations. Am I correct? What about other events like preemptions, activations, terminations?

Right now, indeed, the only things we needed to track were migrations and job begin times. The tool allows you to track more with very little modifications (a compilation flag for job termination, and a couple of flags to add in the launch script for the preemptions, scheduler interventions and for every time a task change queue (a superset of activations).

More precisely, if you look at line 19 in the compilation script there is a comment with name of events that can be enabled at the application level (like lock acquisition - TRACE_LOCK_ACQUIRED -, or job termination - TRACE_END_LOOP). This is the way to enable application-dependent events. For scheduler-dependent events, if you look at lines 87 to 90 in the launcher script, there are already other events that can be tracked commented. For example, it is just enough to add the event (-e) of line 89 in line 94 (where now there are only migrations) to generate an event (that is then tracked) every time the scheduler wakes up and wants to do something.