Monthly Archives: February 2011

Using –pid and –tid to record samples in specific threads

To test that a patch I wrote to fix a problem reported on lkml I ended up writing a changeset comment I think its worth sharing here, as it demonstrates how to use the –pid and –tid command line options available in perf record and perf top, so here it goes.

Jeff Moyer reported these messages:

      Warning:  ... trying to fall back to cpu-clock-ticks
    
    couldn't open /proc/-1/status
    couldn't open /proc/-1/maps
    [ls output]
    [ perf record: Woken up 1 times to write data ]
    [ perf record: Captured and wrote 0.008 MB perf.data (~363 samples) ]

That lead me and David Ahern to see that something was fishy on the thread synthesizing routines, at least for the case where the workload is started from perf record, as -1 is the default for target_tid in perf record –tid parameter, so somehow we were trying to synthesize the PERF_RECORD_MMAP and PERF_RECORD_COMM events for the thread -1, a bug.

So I investigated this and noticed that when we introduced support for recording a process and its threads using –pid some bugs were introduced and that the way to fix it was to instead of passing the target_tid to the event synthesizing routines we should better pass the thread_map that has the list of threads for a –pid or just the single thread for a –tid.

Checked in the following ways:

On a 8-way machine run cyclictest:

    [root@emilia ~]# perf record cyclictest -a -t -n -p99 -i100 -d50
    policy: fifo: loadavg: 0.00 0.13 0.31 2/139 28798
    
    T: 0 (28791) P:99 I:100 C:  25072 Min:      4 Act:    5 Avg:    6 Max:     122
    T: 1 (28792) P:98 I:150 C:  16715 Min:      4 Act:    6 Avg:    5 Max:      27
    T: 2 (28793) P:97 I:200 C:  12534 Min:      4 Act:    5 Avg:    4 Max:       8
    T: 3 (28794) P:96 I:250 C:  10028 Min:      4 Act:    5 Avg:    5 Max:      96
    T: 4 (28795) P:95 I:300 C:   8357 Min:      5 Act:    6 Avg:    5 Max:      12
    T: 5 (28796) P:94 I:350 C:   7163 Min:      5 Act:    6 Avg:    5 Max:      12
    T: 6 (28797) P:93 I:400 C:   6267 Min:      4 Act:    5 Avg:    5 Max:       9
    T: 7 (28798) P:92 I:450 C:   5571 Min:      4 Act:    5 Avg:    5 Max:       9
    ^C[ perf record: Woken up 1 times to write data ]
    [ perf record: Captured and wrote 0.108 MB perf.data (~4719 samples) ]
    
    [root@emilia ~]#

This will create one extra thread per CPU:

  [root@emilia ~]# tuna -t cyclictest -CP
                          thread       ctxt_switches
        pid SCHED_ rtpri affinity voluntary nonvoluntary             cmd
     28825   OTHER     0     0xff      2169          671      cyclictest
      28832   FIFO    93        6     52338            1      cyclictest
      28833   FIFO    92        7     46524            1      cyclictest
      28826   FIFO    99        0    209360            1      cyclictest
      28827   FIFO    98        1    139577            1      cyclictest
      28828   FIFO    97        2    104686            0      cyclictest
      28829   FIFO    96        3     83751            1      cyclictest
      28830   FIFO    95        4     69794            1      cyclictest
      28831   FIFO    94        5     59825            1      cyclictest
    [root@emilia ~]#

So we should expect only samples for the above 9 threads when using the –dump-raw-trace|-D perf report switch to look at the column with the tid:

    [root@emilia ~]# perf report -D | grep RECORD_SAMPLE | cut -d/ -f2 | cut -d: -f1 | sort | uniq -c
        629 28825
        110 28826
        491 28827
        308 28828
        198 28829
        621 28830
        225 28831
        203 28832
         89 28833
    [root@emilia ~]#

So for workloads started by perf record it seems to work, now for existing workloads, just ran cyclictest first, without perf record:

    [root@emilia ~]# tuna -t cyclictest -CP
                          thread       ctxt_switches
        pid SCHED_ rtpri affinity voluntary nonvoluntary             cmd
     28859   OTHER     0     0xff       594          200      cyclictest
      28864   FIFO    95        4     16587            1      cyclictest
      28865   FIFO    94        5     14219            1      cyclictest
      28866   FIFO    93        6     12443            0      cyclictest
      28867   FIFO    92        7     11062            1      cyclictest
      28860   FIFO    99        0     49779            1      cyclictest
      28861   FIFO    98        1     33190            1      cyclictest
      28862   FIFO    97        2     24895            1      cyclictest
      28863   FIFO    96        3     19918            1      cyclictest
    [root@emilia ~]#

and then later did:

    [root@emilia ~]# perf record --pid 28859 sleep 3
    [ perf record: Woken up 1 times to write data ]
    [ perf record: Captured and wrote 0.027 MB perf.data (~1195 samples) ]

    [root@emilia ~]#

To collect 3 seconds worth of samples for pid 28859 and its children:

    [root@emilia ~]# perf report -D | grep RECORD_SAMPLE | cut -d/ -f2 | cut -d: -f1 | sort | uniq -c
         15 28859
         33 28860
         19 28861
         13 28862
         13 28863
         10 28864
         11 28865
          9 28866
        255 28867
    [root@emilia ~]#

Works, last thing is to check if looking at just one of those threads also works:

    [root@emilia ~]# perf record --tid 28866 sleep 3
    [ perf record: Woken up 1 times to write data ]
    [ perf record: Captured and wrote 0.006 MB perf.data (~242 samples) ]
    [root@emilia ~]# perf report -D | grep RECORD_SAMPLE | cut -d/ -f2 | cut -d: -f1 | sort | uniq -c
          3 28866
    [root@emilia ~]#

Works too.

Follow

Get every new post delivered to your Inbox.