Project

General

Profile

Download (98.5 KB)

Bug #497 » TC17_node16_8KAppFirst_Timer1s_TraceOn1pid_buf16k_100ps_a_b_c.log

Runs with streaming, SwitchTimer 1sec - Tan le tran, 04/09/2013 09:52 AM

 
[SC-1:Node16 Fri Apr 05 10:40:53/cluster/temp/log] # export TC=LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run1
[SC-1:Node16 Fri Apr 05 10:41:19/cluster/temp/log] # DOMAIN_EVENT="com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec"
[SC-1:Node16 Fri Apr 05 10:41:19/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:41:19/cluster/temp/log] # sleep 1
sar -u 1 300 >> $TC.load.log &
netstat -etanp | head -n 2 ; netstat -etanp |egrep 'lttng'
sleep 1
echo "Start to launch apps when no session is active." >> $TC.load.log
#----------------------------------------------------------------------
date; time for n in $(seq 1 8000); do (/home/test_apps/TestApp_100psOnly 200 np &); done
#----------------------------------------------------------------------
echo "End of launching apps when no session is active" >> $TC.load.log
ps -ef |grep -c TestApp
sleep 1

#---------------------------- Get PID to trace on --------------------------------------------------
export my_pid=$(ps -e |grep TestApp | tail -n 1 | awk {'print $1'}); echo $my_pid
sleep 10

ps -ef |egrep 'lttng'
lttng-relayd -C tcp://0.0.0.0:53000 -D tcp://0.0.0.0:53001 -o /cluster/temp/log/$TC &
echo "Create the session." >> $TC.load.log
date; lttng create $TC -U net://192.168.0.1:53000:53001/./
lttng list
sleep 5
echo "Enable channel...." >> $TC.load.log
date; lttng enable-channel chan1 -u -s $TC --buffers-uid --subbuf-size 16384 --switch-timer 1000000
echo "Enable channel done." >> $TC.load.log
echo "Enable channel metadata...." >> $TC.load.log
date; lttng enable-channel metadata -u -s $TC --buffers-uid --subbuf-size 16384 --switch-timer 1000000
echo "Enable channel metadata done." >> $TC.load.log
sleep 5
lttng add-context -t vpid -u -s $TC
echo "Enable Event...." >> $TC.load.log
date; lttng enable-event -s $TC -u -c chan1 $DOMAIN_EVENT --filter "PID == $my_pid"
echo "Enable Event done." >> $TC.load.log
sleep 5

echo "Activate the session." >> $TC.load.log
#---------------------------------------------------- activate session -----------------------
date; lttng start;
echo "Activate session Done." >> $TC.load.log
sleep 1
lttng list $TC
sleep 1
ps -e |grep -c TestApp
dir -R $TC/SC-1/ust/uid/0/64-bit
sleep 1
dir -R $TC/SC-1/ust/uid/0/64-bit
sleep 1
dir -R $TC/SC-1/ust/uid/0/64-bit
sleep 1
dir -R $TC/SC-1/ust/uid/0/64-bit
sleep 1
dir -R $TC/SC-1/ust/uid/0/64-bit
sleep 5
dir -R $TC/SC-1/ust/uid/0/64-bit
echo "Stopping the session..." >> $TC.load.log
#---------------------------------------------------- De-activate session -----------------------
lttng stop
echo "Stopping done." >> $TC.load.log
sleep 1
dir -R $TC/SC-1/ust/uid/0/64-bit
sleep 5
echo "Destroying the session..." >> $TC.load.log
lttng destroy
echo "Destroy done! " >> $TC.load.log
sleep 5
dir -R $TC/SC-1/ust/uid/0/64-bit
pkill relayd

babeltrace $TC | head -n 10
sleep 1
dir /cluster/dumps
sleep 5
echo "Killing TestApp" >> $TC.load.log
ps -e |grep -c TestApp
pkill TestApp
echo "Killing Done ." >> $TC.load.log
ps -e |grep -c TestApp
sleep 5
pkill sar

cat $TC.load.log

rm $TC.load.log
babeltrace $TC | grep -c $DOMAIN_EVENT
du -h $TC | tail -n 1
[SC-1:Node16 Fri Apr 05 10:41:20/cluster/temp/log] # sar -u 1 300 >> $TC.load.log &
[1] 30544
[SC-1:Node16 Fri Apr 05 10:41:20/cluster/temp/log] # netstat -etanp | head -n 2 ; netstat -etanp |egrep 'lttng'
Active Internet connections (servers and established)
Proto Recv-Q Send-Q Local Address Foreign Address State User Inode PID/Program name
[SC-1:Node16 Fri Apr 05 10:41:20/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:41:21/cluster/temp/log] # echo "Start to launch apps when no session is active." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:41:21/cluster/temp/log] # #----------------------------------------------------------------------
[SC-1:Node16 Fri Apr 05 10:41:21/cluster/temp/log] # date; time for n in $(seq 1 8000); do (/home/test_apps/TestApp_100psOnly 200 np &); done
Fri Apr 5 10:41:21 EDT 2013

real 0m27.664s
user 0m2.480s
sys 0m1.656s
[SC-1:Node16 Fri Apr 05 10:41:49/cluster/temp/log] # #----------------------------------------------------------------------
[SC-1:Node16 Fri Apr 05 10:41:49/cluster/temp/log] # echo "End of launching apps when no session is active" >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:41:49/cluster/temp/log] # ps -ef |grep -c TestApp
8001
[SC-1:Node16 Fri Apr 05 10:41:50/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:41:51/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:41:51/cluster/temp/log] # #---------------------------- Get PID to trace on --------------------------------------------------
[SC-1:Node16 Fri Apr 05 10:41:51/cluster/temp/log] # export my_pid=$(ps -e |grep TestApp | tail -n 1 | awk {'print $1'}); echo $my_pid
32766
[SC-1:Node16 Fri Apr 05 10:41:52/cluster/temp/log] # sleep 10
[SC-1:Node16 Fri Apr 05 10:42:02/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:42:02/cluster/temp/log] # ps -ef |egrep 'lttng'
root 13798 1 0 Apr03 ? 00:02:38 lttng-sessiond -d
root 30433 4536 0 10:42 pts/1 00:00:00 egrep lttng
root 31628 13798 0 Apr03 ? 00:01:44 lttng-consumerd --quiet -u --consumerd-cmd-sock /var/run/lttng/ustconsumerd64/command --consumerd-err-sock /var/run/lttng/ustconsumerd64/error
[SC-1:Node16 Fri Apr 05 10:42:03/cluster/temp/log] # lttng-relayd -C tcp://0.0.0.0:53000 -D tcp://0.0.0.0:53001 -o /cluster/temp/log/$TC &
[2] 30434
[SC-1:Node16 Fri Apr 05 10:42:03/cluster/temp/log] # echo "Create the session." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:42:03/cluster/temp/log] # date; lttng create $TC -U net://192.168.0.1:53000:53001/./
Fri Apr 5 10:42:03 EDT 2013
Session LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run1 created.
Traces will be written in net://192.168.0.1:53000:53001/./
[SC-1:Node16 Fri Apr 05 10:42:03/cluster/temp/log] # lttng list
Available tracing sessions:
1) LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run1 (net://192.168.0.1:53000/./ [data: 5343]) [inactive]

Use lttng list <session_name> for more details
[SC-1:Node16 Fri Apr 05 10:42:03/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:42:08/cluster/temp/log] # echo "Enable channel...." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:42:08/cluster/temp/log] # date; lttng enable-channel chan1 -u -s $TC --buffers-uid --subbuf-size 16384 --switch-timer 1000000
Fri Apr 5 10:42:08 EDT 2013
UST channel chan1 enabled for session LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run1
[SC-1:Node16 Fri Apr 05 10:42:16/cluster/temp/log] # echo "Enable channel done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:42:16/cluster/temp/log] # echo "Enable channel metadata...." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:42:16/cluster/temp/log] # date; lttng enable-channel metadata -u -s $TC --buffers-uid --subbuf-size 16384 --switch-timer 1000000
Fri Apr 5 10:42:16 EDT 2013
UST channel metadata enabled for session LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run1
[SC-1:Node16 Fri Apr 05 10:42:16/cluster/temp/log] # echo "Enable channel metadata done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:42:16/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:42:21/cluster/temp/log] # lttng add-context -t vpid -u -s $TC
UST context vpid added to all channels
[SC-1:Node16 Fri Apr 05 10:42:21/cluster/temp/log] # echo "Enable Event...." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:42:22/cluster/temp/log] # date; lttng enable-event -s $TC -u -c chan1 $DOMAIN_EVENT --filter "PID == $my_pid"
Fri Apr 5 10:42:22 EDT 2013
Filter 'PID == 32766' successfully set
[SC-1:Node16 Fri Apr 05 10:42:23/cluster/temp/log] # echo "Enable Event done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:42:23/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:42:28/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:42:28/cluster/temp/log] # echo "Activate the session." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:42:28/cluster/temp/log] # #---------------------------------------------------- activate session -----------------------
[SC-1:Node16 Fri Apr 05 10:42:28/cluster/temp/log] # date; lttng start;
Fri Apr 5 10:42:28 EDT 2013
Tracing started for session LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run1
[SC-1:Node16 Fri Apr 05 10:42:35/cluster/temp/log] # echo "Activate session Done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:42:35/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:42:36/cluster/temp/log] # lttng list $TC
Tracing session LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run1: [active]
Trace path: net://192.168.0.1:53000/./ [data: 53001]

=== Domain: UST global ===

Channels:
-------------
- metadata: [enabled]

Attributes:
overwrite mode: 0
subbufers size: 16384
number of subbufers: 4
switch timer interval: 1000000
read timer interval: 200000
output: mmap()

Events:
None

- chan1: [enabled]

Attributes:
overwrite mode: 0
subbufers size: 16384
number of subbufers: 4
switch timer interval: 1000000
read timer interval: 200000
output: mmap()

Events:
com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec (type: tracepoint) [enabled] [with filter]

[SC-1:Node16 Fri Apr 05 10:42:36/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:42:37/cluster/temp/log] # ps -e |grep -c TestApp
8000
[SC-1:Node16 Fri Apr 05 10:42:38/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run1/SC-1/ust/uid/0/64-bit:
total 104
-rw-rw---- 1 root root 12288 Apr 5 10:42 metadata
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_9
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_8
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_7
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_6
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_5
-rw-rw---- 1 root root 8192 Apr 5 10:42 chan1_4
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_3
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_2
-rw-rw---- 1 root root 24576 Apr 5 10:42 chan1_11
-rw-rw---- 1 root root 24576 Apr 5 10:42 chan1_10
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_1
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_0
[SC-1:Node16 Fri Apr 05 10:42:38/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:42:39/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run1/SC-1/ust/uid/0/64-bit:
total 112
-rw-rw---- 1 root root 12288 Apr 5 10:42 metadata
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_9
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_8
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_7
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_6
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_5
-rw-rw---- 1 root root 8192 Apr 5 10:42 chan1_4
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_3
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_2
-rw-rw---- 1 root root 24576 Apr 5 10:42 chan1_11
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_1
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_0
-rw-rw---- 1 root root 32768 Apr 5 10:42 chan1_10
[SC-1:Node16 Fri Apr 05 10:42:39/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:42:40/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run1/SC-1/ust/uid/0/64-bit:
total 124
-rw-rw---- 1 root root 12288 Apr 5 10:42 metadata
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_9
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_8
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_7
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_6
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_5
-rw-rw---- 1 root root 8192 Apr 5 10:42 chan1_4
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_3
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_2
-rw-rw---- 1 root root 24576 Apr 5 10:42 chan1_11
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_0
-rw-rw---- 1 root root 36864 Apr 5 10:42 chan1_10
-rw-rw---- 1 root root 12288 Apr 5 10:42 chan1_1
[SC-1:Node16 Fri Apr 05 10:42:40/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:42:41/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run1/SC-1/ust/uid/0/64-bit:
total 140
-rw-rw---- 1 root root 12288 Apr 5 10:42 metadata
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_9
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_8
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_7
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_6
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_5
-rw-rw---- 1 root root 8192 Apr 5 10:42 chan1_4
-rw-rw---- 1 root root 24576 Apr 5 10:42 chan1_11
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_0
-rw-rw---- 1 root root 36864 Apr 5 10:42 chan1_10
-rw-rw---- 1 root root 8192 Apr 5 10:42 chan1_3
-rw-rw---- 1 root root 8192 Apr 5 10:42 chan1_2
-rw-rw---- 1 root root 20480 Apr 5 10:42 chan1_1
[SC-1:Node16 Fri Apr 05 10:42:41/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:42:42/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run1/SC-1/ust/uid/0/64-bit:
total 148
-rw-rw---- 1 root root 12288 Apr 5 10:42 metadata
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_9
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_8
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_7
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_6
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_5
-rw-rw---- 1 root root 8192 Apr 5 10:42 chan1_4
-rw-rw---- 1 root root 24576 Apr 5 10:42 chan1_11
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_0
-rw-rw---- 1 root root 36864 Apr 5 10:42 chan1_10
-rw-rw---- 1 root root 8192 Apr 5 10:42 chan1_2
-rw-rw---- 1 root root 20480 Apr 5 10:42 chan1_1
-rw-rw---- 1 root root 16384 Apr 5 10:42 chan1_3
[SC-1:Node16 Fri Apr 05 10:42:43/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:42:48/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run1/SC-1/ust/uid/0/64-bit:
total 196
-rw-rw---- 1 root root 12288 Apr 5 10:42 metadata
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_8
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_7
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_6
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_5
-rw-rw---- 1 root root 8192 Apr 5 10:42 chan1_4
-rw-rw---- 1 root root 24576 Apr 5 10:42 chan1_11
-rw-rw---- 1 root root 36864 Apr 5 10:42 chan1_10
-rw-rw---- 1 root root 36864 Apr 5 10:42 chan1_9
-rw-rw---- 1 root root 20480 Apr 5 10:42 chan1_3
-rw-rw---- 1 root root 12288 Apr 5 10:42 chan1_2
-rw-rw---- 1 root root 24576 Apr 5 10:42 chan1_1
-rw-rw---- 1 root root 8192 Apr 5 10:42 chan1_0
[SC-1:Node16 Fri Apr 05 10:42:48/cluster/temp/log] # echo "Stopping the session..." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:42:48/cluster/temp/log] # #---------------------------------------------------- De-activate session -----------------------
[SC-1:Node16 Fri Apr 05 10:42:48/cluster/temp/log] # lttng stop
Waiting for data availability
Tracing stopped for session LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run1
[SC-1:Node16 Fri Apr 05 10:42:51/cluster/temp/log] # echo "Stopping done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:42:51/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:42:52/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run1/SC-1/ust/uid/0/64-bit:
total 1324
-rw-rw---- 1 root root 12288 Apr 5 10:42 metadata
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_8
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_7
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_6
-rw-rw---- 1 root root 4096 Apr 5 10:42 chan1_5
-rw-rw---- 1 root root 8192 Apr 5 10:42 chan1_4
-rw-rw---- 1 root root 24576 Apr 5 10:42 chan1_11
-rw-rw---- 1 root root 36864 Apr 5 10:42 chan1_10
-rw-rw---- 1 root root 36864 Apr 5 10:42 chan1_9
-rw-rw---- 1 root root 303104 Apr 5 10:42 chan1_3
-rw-rw---- 1 root root 282624 Apr 5 10:42 chan1_2
-rw-rw---- 1 root root 536576 Apr 5 10:42 chan1_1
-rw-rw---- 1 root root 81920 Apr 5 10:42 chan1_0
[SC-1:Node16 Fri Apr 05 10:42:52/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:42:57/cluster/temp/log] # echo "Destroying the session..." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:42:57/cluster/temp/log] # lttng destroy
Session LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run1 destroyed
[SC-1:Node16 Fri Apr 05 10:42:59/cluster/temp/log] # echo "Destroy done! " >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:42:59/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:43:04/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run1/SC-1/ust/uid/0/64-bit:
total 1376
-rw-rw---- 1 root root 16384 Apr 5 10:42 metadata
-rw-rw---- 1 root root 40960 Apr 5 10:42 chan1_9
-rw-rw---- 1 root root 8192 Apr 5 10:42 chan1_8
-rw-rw---- 1 root root 8192 Apr 5 10:42 chan1_7
-rw-rw---- 1 root root 8192 Apr 5 10:42 chan1_6
-rw-rw---- 1 root root 8192 Apr 5 10:42 chan1_5
-rw-rw---- 1 root root 12288 Apr 5 10:42 chan1_4
-rw-rw---- 1 root root 307200 Apr 5 10:42 chan1_3
-rw-rw---- 1 root root 286720 Apr 5 10:42 chan1_2
-rw-rw---- 1 root root 28672 Apr 5 10:42 chan1_11
-rw-rw---- 1 root root 40960 Apr 5 10:42 chan1_10
-rw-rw---- 1 root root 540672 Apr 5 10:42 chan1_1
-rw-rw---- 1 root root 86016 Apr 5 10:42 chan1_0
[SC-1:Node16 Fri Apr 05 10:43:04/cluster/temp/log] # pkill relayd
[SC-1:Node16 Fri Apr 05 10:43:04/cluster/temp/log] #
[2]+ Done lttng-relayd -C tcp://0.0.0.0:53000 -D tcp://0.0.0.0:53001 -o /cluster/temp/log/$TC
[SC-1:Node16 Fri Apr 05 10:43:04/cluster/temp/log] # babeltrace $TC | head -n 10
[10:42:33.436478958] (+?.?????????) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 11 }, { vpid = 32766 }, { my_Time = "10:42:33", PID = 32766, OnePs = 70, TenPs = 3, HundredPs = 9, unit_float = 9.1234, unit_string = "unit_9" }
[10:42:33.446883188] (+0.010404230) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 11 }, { vpid = 32766 }, { my_Time = "10:42:33", PID = 32766, OnePs = 70, TenPs = 4, HundredPs = 0, unit_float = 0.1234, unit_string = "unit_0" }
[10:42:33.456517596] (+0.009634408) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 11 }, { vpid = 32766 }, { my_Time = "10:42:33", PID = 32766, OnePs = 70, TenPs = 4, HundredPs = 1, unit_float = 1.1234, unit_string = "unit_1" }
[10:42:33.466911250] (+0.010393654) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 11 }, { vpid = 32766 }, { my_Time = "10:42:33", PID = 32766, OnePs = 70, TenPs = 4, HundredPs = 2, unit_float = 2.1234, unit_string = "unit_2" }
[10:42:33.477044622] (+0.010133372) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 11 }, { vpid = 32766 }, { my_Time = "10:42:33", PID = 32766, OnePs = 70, TenPs = 4, HundredPs = 3, unit_float = 3.1234, unit_string = "unit_3" }
[10:42:33.486907445] (+0.009862823) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 11 }, { vpid = 32766 }, { my_Time = "10:42:33", PID = 32766, OnePs = 70, TenPs = 4, HundredPs = 4, unit_float = 4.1234, unit_string = "unit_4" }
[10:42:33.496903696] (+0.009996251) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 11 }, { vpid = 32766 }, { my_Time = "10:42:33", PID = 32766, OnePs = 70, TenPs = 4, HundredPs = 5, unit_float = 5.1234, unit_string = "unit_5" }
[10:42:33.506911930] (+0.010008234) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 11 }, { vpid = 32766 }, { my_Time = "10:42:33", PID = 32766, OnePs = 70, TenPs = 4, HundredPs = 6, unit_float = 6.1234, unit_string = "unit_6" }
[10:42:33.517034223] (+0.010122293) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 11 }, { vpid = 32766 }, { my_Time = "10:42:33", PID = 32766, OnePs = 70, TenPs = 4, HundredPs = 7, unit_float = 7.1234, unit_string = "unit_7" }
[10:42:33.527050600] (+0.010016377) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 11 }, { vpid = 32766 }, { my_Time = "10:42:33", PID = 32766, OnePs = 70, TenPs = 4, HundredPs = 8, unit_float = 8.1234, unit_string = "unit_8" }
[SC-1:Node16 Fri Apr 05 10:43:04/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:43:05/cluster/temp/log] # dir /cluster/dumps
total 0
[SC-1:Node16 Fri Apr 05 10:43:05/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:43:10/cluster/temp/log] # echo "Killing TestApp" >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:43:10/cluster/temp/log] # ps -e |grep -c TestApp
8000
[SC-1:Node16 Fri Apr 05 10:43:11/cluster/temp/log] # pkill TestApp
[SC-1:Node16 Fri Apr 05 10:43:16/cluster/temp/log] # echo "Killing Done ." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:43:16/cluster/temp/log] # ps -e |grep -c TestApp
0
[SC-1:Node16 Fri Apr 05 10:43:16/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:43:21/cluster/temp/log] # pkill sar
[SC-1:Node16 Fri Apr 05 10:43:21/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:43:21/cluster/temp/log] # cat $TC.load.log
Linux 3.0.42-0.7.3.4775.1.PTF-default (SC-1) 04/05/13 _x86_64_

10:41:20 CPU %user %nice %system %iowait %steal %idle
10:41:21 all 0.08 0.00 0.42 0.00 0.00 99.50
Start to launch apps when no session is active.
10:41:22 all 7.58 0.00 10.14 0.43 0.00 81.86
10:41:23 all 10.49 0.00 11.68 0.00 0.00 77.83
10:41:24 all 12.37 0.00 12.11 0.00 0.00 75.52
10:41:25 all 14.09 0.00 12.71 0.00 0.00 73.21
10:41:26 all 15.40 0.00 15.22 0.00 0.00 69.38
10:41:27 all 14.62 0.00 17.32 0.00 0.00 68.06
10:41:28 all 15.55 0.00 18.43 0.00 0.00 66.03
10:41:29 all 17.36 0.00 20.42 0.00 0.00 62.22
10:41:30 all 17.74 0.00 20.89 0.00 0.00 61.36
10:41:31 all 18.67 0.00 21.90 0.00 0.00 59.42
10:41:32 all 20.38 0.00 25.09 0.00 0.00 54.54
10:41:33 all 23.18 0.00 23.94 0.00 0.00 52.88
10:41:34 all 23.19 0.00 27.30 0.00 0.00 49.51
10:41:35 all 24.41 0.00 28.87 0.00 0.00 46.72
10:41:36 all 25.29 0.00 27.85 0.00 0.00 46.86
10:41:37 all 25.81 0.00 28.87 0.00 0.00 45.33
10:41:38 all 26.48 0.00 29.44 0.00 0.00 44.08
10:41:39 all 26.93 0.00 29.99 0.00 0.00 43.08
10:41:40 all 27.57 0.00 30.41 0.00 0.00 42.02
10:41:41 all 27.65 0.00 31.59 0.00 0.00 40.75
10:41:42 all 30.41 0.00 32.89 0.00 0.00 36.69
10:41:43 all 27.94 0.00 32.51 0.00 0.00 39.54
10:41:44 all 29.77 0.00 31.45 0.00 0.00 38.78
10:41:45 all 29.82 0.00 34.60 0.00 0.00 35.58
10:41:46 all 29.62 0.00 33.78 0.00 0.00 36.60
10:41:47 all 32.23 0.00 33.76 0.00 0.00 34.01
10:41:48 all 30.95 0.00 38.11 0.00 0.00 30.95
End of launching apps when no session is active
10:41:49 all 31.85 0.00 33.60 0.17 0.00 34.38
10:41:50 all 31.14 0.00 32.26 0.00 0.00 36.60
10:41:51 all 29.47 0.00 33.73 0.00 0.00 36.80
10:41:52 all 29.57 0.00 33.72 0.00 0.00 36.71
10:41:53 all 30.54 0.00 30.62 0.00 0.00 38.85
10:41:54 all 30.87 0.00 33.41 0.00 0.00 35.72
10:41:55 all 31.28 0.00 30.33 0.00 0.00 38.39
10:41:56 all 30.17 0.00 30.73 0.00 0.00 39.10
10:41:57 all 28.97 0.00 35.04 0.00 0.00 35.99
10:41:58 all 30.69 0.00 29.46 0.00 0.00 39.85
10:41:59 all 29.70 0.00 32.43 0.00 0.00 37.87
10:42:00 all 29.12 0.00 34.64 0.00 0.00 36.24
10:42:01 all 30.07 0.00 32.18 0.00 0.00 37.74
10:42:02 all 30.03 0.00 35.14 0.00 0.00 34.83
Create the session.
10:42:03 all 31.94 0.00 34.23 0.25 0.00 33.58
10:42:04 all 27.75 0.00 32.87 0.00 0.00 39.39
10:42:05 all 30.24 0.00 29.50 0.00 0.00 40.26
10:42:06 all 29.95 0.00 33.75 0.00 0.00 36.30
10:42:07 all 29.64 0.00 32.45 0.00 0.00 37.91
Enable channel....
10:42:08 all 29.45 0.00 32.87 0.49 0.00 37.19
10:42:09 all 32.01 0.00 36.30 0.00 0.00 31.69
10:42:10 all 31.43 0.00 36.90 0.00 0.00 31.67
10:42:11 all 31.97 0.00 35.34 0.00 0.00 32.69
10:42:12 all 29.60 0.00 36.24 0.00 0.00 34.16
10:42:13 all 30.74 0.00 36.68 0.00 0.00 32.58
10:42:14 all 32.09 0.00 32.68 0.00 0.00 35.22
10:42:15 all 31.47 0.00 33.22 0.00 0.00 35.31
Enable channel done.
Enable channel metadata....
Enable channel metadata done.
10:42:16 all 31.05 0.00 35.14 0.33 0.00 33.47
10:42:17 all 28.69 0.00 32.07 0.00 0.00 39.24
10:42:18 all 29.21 0.00 31.41 0.00 0.00 39.38
10:42:19 all 30.22 0.00 31.49 0.00 0.00 38.29
10:42:20 all 29.42 0.00 30.40 0.00 0.00 40.18
10:42:21 all 29.79 0.00 32.20 0.00 0.00 38.01
Enable Event....
10:42:22 all 32.61 0.00 36.48 0.16 0.00 30.75
Enable Event done.
10:42:23 all 33.20 0.00 29.81 0.16 0.00 36.83
10:42:24 all 30.32 0.00 29.83 0.00 0.00 39.85
10:42:25 all 29.92 0.00 35.00 0.00 0.00 35.08
10:42:26 all 32.13 0.00 31.07 0.00 0.00 36.80
10:42:27 all 28.27 0.00 34.16 0.00 0.00 37.57
Activate the session.
10:42:28 all 32.00 0.00 35.60 0.08 0.00 32.32
10:42:29 all 38.58 0.00 34.95 0.00 0.00 26.47
10:42:30 all 44.24 0.00 34.62 0.00 0.00 21.13
10:42:31 all 51.11 0.00 34.10 0.00 0.00 14.79
10:42:32 all 51.58 0.00 34.96 0.00 0.00 13.46
10:42:33 all 51.47 0.00 33.42 0.00 0.00 15.11
10:42:34 all 53.88 0.00 33.11 0.00 0.00 13.01
Activate session Done.
10:42:35 all 54.48 0.00 34.46 0.08 0.00 10.98
10:42:36 all 53.42 0.00 31.42 0.00 0.00 15.15
10:42:37 all 53.96 0.00 33.72 0.00 0.00 12.32
10:42:38 all 56.52 0.00 37.71 0.17 0.00 5.60
10:42:39 all 54.86 0.00 30.31 0.33 0.00 14.50
10:42:40 all 55.45 0.00 30.12 0.00 0.00 14.44
10:42:41 all 53.03 0.00 34.67 0.00 0.00 12.30
10:42:42 all 55.89 0.00 27.77 0.18 0.00 16.17
10:42:43 all 56.32 0.00 28.16 0.00 0.00 15.53
10:42:44 all 57.36 0.00 30.95 0.00 0.00 11.69
10:42:45 all 53.87 0.00 31.47 0.00 0.00 14.65
10:42:46 all 52.90 0.00 32.09 0.00 0.00 15.01
10:42:47 all 55.77 0.00 32.77 0.00 0.00 11.46
Stopping the session...
10:42:48 all 51.66 0.00 33.81 0.17 0.00 14.36
10:42:49 all 49.21 0.00 32.54 0.00 0.00 18.25
10:42:50 all 39.60 0.00 37.71 0.00 0.00 22.69
Stopping done.
10:42:51 all 30.73 0.00 33.12 0.24 0.00 35.91
10:42:52 all 28.24 0.00 32.36 0.00 0.00 39.40
10:42:53 all 28.56 0.00 33.33 0.00 0.00 38.11
10:42:54 all 29.34 0.00 31.49 0.00 0.00 39.17
10:42:55 all 30.07 0.00 31.70 0.00 0.00 38.23
10:42:56 all 32.71 0.00 32.16 0.00 0.00 35.14
Destroying the session...
10:42:57 all 30.37 0.00 33.09 0.08 0.00 36.46
10:42:58 all 30.55 0.00 36.00 0.00 0.00 33.44
Destroy done!
10:42:59 all 29.65 0.00 36.70 1.36 0.00 32.29
10:43:00 all 29.34 0.00 29.09 0.00 0.00 41.57
10:43:01 all 28.93 0.00 31.10 0.00 0.00 39.97
10:43:02 all 28.02 0.00 35.31 0.00 0.00 36.67
10:43:03 all 28.85 0.00 32.57 0.00 0.00 38.58
10:43:04 all 30.35 0.00 32.95 0.00 0.00 36.70
10:43:05 all 31.84 0.00 32.68 0.00 0.00 35.48
10:43:06 all 29.42 0.00 32.37 0.00 0.00 38.21
10:43:07 all 26.28 0.00 34.11 0.00 0.00 39.62
10:43:08 all 28.20 0.00 31.04 0.00 0.00 40.76
10:43:09 all 31.63 0.00 28.52 0.00 0.00 39.85
Killing TestApp
10:43:10 all 28.55 0.00 31.34 0.16 0.00 39.95
10:43:11 all 29.14 0.00 37.33 0.00 0.00 33.53
10:43:12 all 25.86 0.00 55.94 0.00 0.00 18.20
10:43:13 all 22.46 0.00 59.28 0.07 0.00 18.19
10:43:14 all 17.50 0.00 56.35 0.00 0.00 26.16
10:43:15 all 10.89 0.00 56.27 0.00 0.00 32.84
Killing Done .
10:43:16 all 2.29 0.00 23.31 0.42 0.00 73.98
10:43:17 all 0.17 0.00 5.10 0.00 0.00 94.74
10:43:18 all 0.00 0.00 0.08 0.00 0.00 99.92
10:43:19 all 0.00 0.00 0.17 0.00 0.00 99.83
10:43:20 all 0.00 0.00 0.00 0.00 0.00 100.00
[1]+ Terminated sar -u 1 300 >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:43:21/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:43:21/cluster/temp/log] # rm $TC.load.log
[SC-1:Node16 Fri Apr 05 10:43:21/cluster/temp/log] # babeltrace $TC | grep -c $DOMAIN_EVENT
1760
[SC-1:Node16 Fri Apr 05 10:43:21/cluster/temp/log] # du -h $TC | tail -n 1
1.4M LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run1
[SC-1:Node16 Fri Apr 05 10:43:21/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:43:44/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:43:44/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:43:45/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:43:45/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:43:45/cluster/temp/log] # export TC=LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run2
[SC-1:Node16 Fri Apr 05 10:44:05/cluster/temp/log] # DOMAIN_EVENT="com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec"
[SC-1:Node16 Fri Apr 05 10:44:05/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:44:05/cluster/temp/log] # sleep 1
sar -u 1 300 >> $TC.load.log &
netstat -etanp | head -n 2 ; netstat -etanp |egrep 'lttng'
sleep 1
echo "Start to launch apps when no session is active." >> $TC.load.log
#----------------------------------------------------------------------
date; time for n in $(seq 1 8000); do (/home/test_apps/TestApp_100psOnly 200 np &); done
#----------------------------------------------------------------------
echo "End of launching apps when no session is active" >> $TC.load.log
ps -ef |grep -c TestApp
sleep 1

#---------------------------- Get PID to trace on --------------------------------------------------
export my_pid=$(ps -e |grep TestApp | tail -n 1 | awk {'print $1'}); echo $my_pid
sleep 10

ps -ef |egrep 'lttng'
lttng-relayd -C tcp://0.0.0.0:53000 -D tcp://0.0.0.0:53001 -o /cluster/temp/log/$TC &
echo "Create the session." >> $TC.load.log
date; lttng create $TC -U net://192.168.0.1:53000:53001/./
lttng list
sleep 5
echo "Enable channel...." >> $TC.load.log
date; lttng enable-channel chan1 -u -s $TC --buffers-uid --subbuf-size 16384 --switch-timer 1000000
echo "Enable channel done." >> $TC.load.log
echo "Enable channel metadata...." >> $TC.load.log
date; lttng enable-channel metadata -u -s $TC --buffers-uid --subbuf-size 16384 --switch-timer 1000000
echo "Enable channel metadata done." >> $TC.load.log
sleep 5
lttng add-context -t vpid -u -s $TC
echo "Enable Event...." >> $TC.load.log
date; lttng enable-event -s $TC -u -c chan1 $DOMAIN_EVENT --filter "PID == $my_pid"
echo "Enable Event done." >> $TC.load.log
sleep 5

echo "Activate the session." >> $TC.load.log
#---------------------------------------------------- activate session -----------------------
date; lttng start;
echo "Activate session Done." >> $TC.load.log
sleep 1
lttng list $TC
sleep 1
ps -e |grep -c TestApp
dir -R $TC/SC-1/ust/uid/0/64-bit
sleep 1
dir -R $TC/SC-1/ust/uid/0/64-bit
sleep 1
dir -R $TC/SC-1/ust/uid/0/64-bit
sleep 1
dir -R $TC/SC-1/ust/uid/0/64-bit
sleep 1
dir -R $TC/SC-1/ust/uid/0/64-bit
sleep 5
dir -R $TC/SC-1/ust/uid/0/64-bit
echo "Stopping the session..." >> $TC.load.log
#---------------------------------------------------- De-activate session -----------------------
lttng stop
echo "Stopping done." >> $TC.load.log
sleep 1
dir -R $TC/SC-1/ust/uid/0/64-bit
sleep 5
echo "Destroying the session..." >> $TC.load.log
lttng destroy
echo "Destroy done! " >> $TC.load.log
sleep 5
dir -R $TC/SC-1/ust/uid/0/64-bit
pkill relayd

babeltrace $TC | head -n 10
sleep 1
dir /cluster/dumps
sleep 5
echo "Killing TestApp" >> $TC.load.log
ps -e |grep -c TestApp
pkill TestApp
echo "Killing Done ." >> $TC.load.log
ps -e |grep -c TestApp
sleep 5
pkill sar

cat $TC.load.log

rm $TC.load.log
babeltrace $TC | grep -c $DOMAIN_EVENT
du -h $TC | tail -n 1
[SC-1:Node16 Fri Apr 05 10:44:06/cluster/temp/log] # sar -u 1 300 >> $TC.load.log &
[1] 24672
[SC-1:Node16 Fri Apr 05 10:44:06/cluster/temp/log] # netstat -etanp | head -n 2 ; netstat -etanp |egrep 'lttng'
Active Internet connections (servers and established)
Proto Recv-Q Send-Q Local Address Foreign Address State User Inode PID/Program name
[SC-1:Node16 Fri Apr 05 10:44:06/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:44:07/cluster/temp/log] # echo "Start to launch apps when no session is active." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:44:07/cluster/temp/log] # #----------------------------------------------------------------------
[SC-1:Node16 Fri Apr 05 10:44:07/cluster/temp/log] # date; time for n in $(seq 1 8000); do (/home/test_apps/TestApp_100psOnly 200 np &); done
Fri Apr 5 10:44:07 EDT 2013

real 0m28.573s
user 0m3.428s
sys 0m1.380s
[SC-1:Node16 Fri Apr 05 10:44:36/cluster/temp/log] # #----------------------------------------------------------------------
[SC-1:Node16 Fri Apr 05 10:44:36/cluster/temp/log] # echo "End of launching apps when no session is active" >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:44:36/cluster/temp/log] # ps -ef |grep -c TestApp
8001
[SC-1:Node16 Fri Apr 05 10:44:37/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:44:38/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:44:38/cluster/temp/log] # #---------------------------- Get PID to trace on --------------------------------------------------
[SC-1:Node16 Fri Apr 05 10:44:38/cluster/temp/log] # export my_pid=$(ps -e |grep TestApp | tail -n 1 | awk {'print $1'}); echo $my_pid
32764
[SC-1:Node16 Fri Apr 05 10:44:39/cluster/temp/log] # sleep 10
[SC-1:Node16 Fri Apr 05 10:44:49/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:44:49/cluster/temp/log] # ps -ef |egrep 'lttng'
root 13798 1 0 Apr03 ? 00:02:46 lttng-sessiond -d
root 24564 4536 0 10:44 pts/1 00:00:00 egrep lttng
root 31628 13798 0 Apr03 ? 00:01:45 lttng-consumerd --quiet -u --consumerd-cmd-sock /var/run/lttng/ustconsumerd64/command --consumerd-err-sock /var/run/lttng/ustconsumerd64/error
[SC-1:Node16 Fri Apr 05 10:44:50/cluster/temp/log] # lttng-relayd -C tcp://0.0.0.0:53000 -D tcp://0.0.0.0:53001 -o /cluster/temp/log/$TC &
[2] 24565
[SC-1:Node16 Fri Apr 05 10:44:50/cluster/temp/log] # echo "Create the session." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:44:50/cluster/temp/log] # date; lttng create $TC -U net://192.168.0.1:53000:53001/./
Fri Apr 5 10:44:50 EDT 2013
Session LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run2 created.
Traces will be written in net://192.168.0.1:53000:53001/./
[SC-1:Node16 Fri Apr 05 10:44:50/cluster/temp/log] # lttng list
Available tracing sessions:
1) LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run2 (net://192.168.0.1:53000/./ [data: 5343]) [inactive]

Use lttng list <session_name> for more details
[SC-1:Node16 Fri Apr 05 10:44:50/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:44:55/cluster/temp/log] # echo "Enable channel...." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:44:55/cluster/temp/log] # date; lttng enable-channel chan1 -u -s $TC --buffers-uid --subbuf-size 16384 --switch-timer 1000000
Fri Apr 5 10:44:55 EDT 2013
UST channel chan1 enabled for session LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run2
[SC-1:Node16 Fri Apr 05 10:45:03/cluster/temp/log] # echo "Enable channel done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:45:03/cluster/temp/log] # echo "Enable channel metadata...." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:45:03/cluster/temp/log] # date; lttng enable-channel metadata -u -s $TC --buffers-uid --subbuf-size 16384 --switch-timer 1000000
Fri Apr 5 10:45:03 EDT 2013
UST channel metadata enabled for session LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run2
[SC-1:Node16 Fri Apr 05 10:45:03/cluster/temp/log] # echo "Enable channel metadata done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:45:03/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:45:08/cluster/temp/log] # lttng add-context -t vpid -u -s $TC
UST context vpid added to all channels
[SC-1:Node16 Fri Apr 05 10:45:09/cluster/temp/log] # echo "Enable Event...." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:45:09/cluster/temp/log] # date; lttng enable-event -s $TC -u -c chan1 $DOMAIN_EVENT --filter "PID == $my_pid"
Fri Apr 5 10:45:09 EDT 2013
Filter 'PID == 32764' successfully set
[SC-1:Node16 Fri Apr 05 10:45:10/cluster/temp/log] # echo "Enable Event done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:45:10/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:45:15/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:45:15/cluster/temp/log] # echo "Activate the session." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:45:15/cluster/temp/log] # #---------------------------------------------------- activate session -----------------------
[SC-1:Node16 Fri Apr 05 10:45:15/cluster/temp/log] # date; lttng start;
Fri Apr 5 10:45:15 EDT 2013
Tracing started for session LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run2
[SC-1:Node16 Fri Apr 05 10:45:22/cluster/temp/log] # echo "Activate session Done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:45:22/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:45:23/cluster/temp/log] # lttng list $TC
Tracing session LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run2: [active]
Trace path: net://192.168.0.1:53000/./ [data: 53001]

=== Domain: UST global ===

Channels:
-------------
- metadata: [enabled]

Attributes:
overwrite mode: 0
subbufers size: 16384
number of subbufers: 4
switch timer interval: 1000000
read timer interval: 200000
output: mmap()

Events:
None

- chan1: [enabled]

Attributes:
overwrite mode: 0
subbufers size: 16384
number of subbufers: 4
switch timer interval: 1000000
read timer interval: 200000
output: mmap()

Events:
com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec (type: tracepoint) [enabled] [with filter]

[SC-1:Node16 Fri Apr 05 10:45:23/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:45:24/cluster/temp/log] # ps -e |grep -c TestApp
8000
[SC-1:Node16 Fri Apr 05 10:45:25/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run2/SC-1/ust/uid/0/64-bit:
total 164
-rw-rw---- 1 root root 12288 Apr 5 10:45 chan1_6
-rw-rw---- 1 root root 12288 Apr 5 10:45 metadata
-rw-rw---- 1 root root 8192 Apr 5 10:45 chan1_9
-rw-rw---- 1 root root 8192 Apr 5 10:45 chan1_8
-rw-rw---- 1 root root 12288 Apr 5 10:45 chan1_7
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_5
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_4
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_3
-rw-rw---- 1 root root 12288 Apr 5 10:45 chan1_2
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_11
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_10
-rw-rw---- 1 root root 53248 Apr 5 10:45 chan1_1
-rw-rw---- 1 root root 24576 Apr 5 10:45 chan1_0
[SC-1:Node16 Fri Apr 05 10:45:26/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:45:27/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run2/SC-1/ust/uid/0/64-bit:
total 188
-rw-rw---- 1 root root 12288 Apr 5 10:45 metadata
-rw-rw---- 1 root root 8192 Apr 5 10:45 chan1_9
-rw-rw---- 1 root root 8192 Apr 5 10:45 chan1_8
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_5
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_4
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_3
-rw-rw---- 1 root root 12288 Apr 5 10:45 chan1_2
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_11
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_10
-rw-rw---- 1 root root 20480 Apr 5 10:45 chan1_7
-rw-rw---- 1 root root 16384 Apr 5 10:45 chan1_6
-rw-rw---- 1 root root 61440 Apr 5 10:45 chan1_1
-rw-rw---- 1 root root 28672 Apr 5 10:45 chan1_0
[SC-1:Node16 Fri Apr 05 10:45:27/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:45:28/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run2/SC-1/ust/uid/0/64-bit:
total 196
-rw-rw---- 1 root root 12288 Apr 5 10:45 metadata
-rw-rw---- 1 root root 8192 Apr 5 10:45 chan1_9
-rw-rw---- 1 root root 8192 Apr 5 10:45 chan1_8
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_5
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_4
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_3
-rw-rw---- 1 root root 12288 Apr 5 10:45 chan1_2
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_11
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_10
-rw-rw---- 1 root root 20480 Apr 5 10:45 chan1_7
-rw-rw---- 1 root root 16384 Apr 5 10:45 chan1_6
-rw-rw---- 1 root root 65536 Apr 5 10:45 chan1_1
-rw-rw---- 1 root root 32768 Apr 5 10:45 chan1_0
[SC-1:Node16 Fri Apr 05 10:45:28/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:45:29/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run2/SC-1/ust/uid/0/64-bit:
total 204
-rw-rw---- 1 root root 12288 Apr 5 10:45 metadata
-rw-rw---- 1 root root 8192 Apr 5 10:45 chan1_9
-rw-rw---- 1 root root 8192 Apr 5 10:45 chan1_8
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_5
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_4
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_3
-rw-rw---- 1 root root 12288 Apr 5 10:45 chan1_2
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_11
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_10
-rw-rw---- 1 root root 20480 Apr 5 10:45 chan1_7
-rw-rw---- 1 root root 16384 Apr 5 10:45 chan1_6
-rw-rw---- 1 root root 69632 Apr 5 10:45 chan1_1
-rw-rw---- 1 root root 36864 Apr 5 10:45 chan1_0
[SC-1:Node16 Fri Apr 05 10:45:29/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:45:30/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run2/SC-1/ust/uid/0/64-bit:
total 220
-rw-rw---- 1 root root 12288 Apr 5 10:45 metadata
-rw-rw---- 1 root root 8192 Apr 5 10:45 chan1_9
-rw-rw---- 1 root root 8192 Apr 5 10:45 chan1_8
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_5
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_4
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_3
-rw-rw---- 1 root root 12288 Apr 5 10:45 chan1_2
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_11
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_10
-rw-rw---- 1 root root 24576 Apr 5 10:45 chan1_7
-rw-rw---- 1 root root 20480 Apr 5 10:45 chan1_6
-rw-rw---- 1 root root 73728 Apr 5 10:45 chan1_1
-rw-rw---- 1 root root 40960 Apr 5 10:45 chan1_0
[SC-1:Node16 Fri Apr 05 10:45:30/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:45:35/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run2/SC-1/ust/uid/0/64-bit:
total 280
-rw-rw---- 1 root root 12288 Apr 5 10:45 metadata
-rw-rw---- 1 root root 8192 Apr 5 10:45 chan1_9
-rw-rw---- 1 root root 8192 Apr 5 10:45 chan1_8
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_5
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_4
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_3
-rw-rw---- 1 root root 12288 Apr 5 10:45 chan1_2
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_11
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_10
-rw-rw---- 1 root root 20480 Apr 5 10:45 chan1_6
-rw-rw---- 1 root root 53248 Apr 5 10:45 chan1_7
-rw-rw---- 1 root root 86016 Apr 5 10:45 chan1_1
-rw-rw---- 1 root root 53248 Apr 5 10:45 chan1_0
[SC-1:Node16 Fri Apr 05 10:45:35/cluster/temp/log] # echo "Stopping the session..." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:45:35/cluster/temp/log] # #---------------------------------------------------- De-activate session -----------------------
[SC-1:Node16 Fri Apr 05 10:45:35/cluster/temp/log] # lttng stop
Waiting for data availability
Tracing stopped for session LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run2
[SC-1:Node16 Fri Apr 05 10:45:38/cluster/temp/log] # echo "Stopping done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:45:38/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:45:39/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run2/SC-1/ust/uid/0/64-bit:
total 312
-rw-rw---- 1 root root 12288 Apr 5 10:45 metadata
-rw-rw---- 1 root root 8192 Apr 5 10:45 chan1_9
-rw-rw---- 1 root root 8192 Apr 5 10:45 chan1_8
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_5
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_4
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_3
-rw-rw---- 1 root root 12288 Apr 5 10:45 chan1_2
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_11
-rw-rw---- 1 root root 4096 Apr 5 10:45 chan1_10
-rw-rw---- 1 root root 20480 Apr 5 10:45 chan1_6
-rw-rw---- 1 root root 86016 Apr 5 10:45 chan1_1
-rw-rw---- 1 root root 53248 Apr 5 10:45 chan1_0
-rw-rw---- 1 root root 86016 Apr 5 10:45 chan1_7
[SC-1:Node16 Fri Apr 05 10:45:39/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:45:44/cluster/temp/log] # echo "Destroying the session..." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:45:44/cluster/temp/log] # lttng destroy
Session LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run2 destroyed
[SC-1:Node16 Fri Apr 05 10:45:47/cluster/temp/log] # echo "Destroy done! " >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:45:47/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:45:52/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run2/SC-1/ust/uid/0/64-bit:
total 364
-rw-rw---- 1 root root 16384 Apr 5 10:45 metadata
-rw-rw---- 1 root root 12288 Apr 5 10:45 chan1_9
-rw-rw---- 1 root root 12288 Apr 5 10:45 chan1_8
-rw-rw---- 1 root root 90112 Apr 5 10:45 chan1_7
-rw-rw---- 1 root root 24576 Apr 5 10:45 chan1_6
-rw-rw---- 1 root root 8192 Apr 5 10:45 chan1_5
-rw-rw---- 1 root root 8192 Apr 5 10:45 chan1_4
-rw-rw---- 1 root root 8192 Apr 5 10:45 chan1_3
-rw-rw---- 1 root root 16384 Apr 5 10:45 chan1_2
-rw-rw---- 1 root root 8192 Apr 5 10:45 chan1_11
-rw-rw---- 1 root root 8192 Apr 5 10:45 chan1_10
-rw-rw---- 1 root root 90112 Apr 5 10:45 chan1_1
-rw-rw---- 1 root root 57344 Apr 5 10:45 chan1_0
[SC-1:Node16 Fri Apr 05 10:45:52/cluster/temp/log] # pkill relayd
[2]+ Done lttng-relayd -C tcp://0.0.0.0:53000 -D tcp://0.0.0.0:53001 -o /cluster/temp/log/$TC
[SC-1:Node16 Fri Apr 05 10:45:52/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:45:52/cluster/temp/log] # babeltrace $TC | head -n 10
[10:45:15.652945344] (+?.?????????) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 0 }, { vpid = 32764 }, { my_Time = "10:45:15", PID = 32764, OnePs = 63, TenPs = 6, HundredPs = 0, unit_float = 0.1234, unit_string = "unit_0" }
[10:45:15.662883497] (+0.009938153) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 1 }, { vpid = 32764 }, { my_Time = "10:45:15", PID = 32764, OnePs = 63, TenPs = 6, HundredPs = 1, unit_float = 1.1234, unit_string = "unit_1" }
[10:45:15.672858871] (+0.009975374) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 7 }, { vpid = 32764 }, { my_Time = "10:45:15", PID = 32764, OnePs = 63, TenPs = 6, HundredPs = 2, unit_float = 2.1234, unit_string = "unit_2" }
[10:45:15.682833790] (+0.009974919) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 7 }, { vpid = 32764 }, { my_Time = "10:45:15", PID = 32764, OnePs = 63, TenPs = 6, HundredPs = 3, unit_float = 3.1234, unit_string = "unit_3" }
[10:45:15.692863259] (+0.010029469) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 7 }, { vpid = 32764 }, { my_Time = "10:45:15", PID = 32764, OnePs = 63, TenPs = 6, HundredPs = 4, unit_float = 4.1234, unit_string = "unit_4" }
[10:45:15.702826693] (+0.009963434) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 7 }, { vpid = 32764 }, { my_Time = "10:45:15", PID = 32764, OnePs = 63, TenPs = 6, HundredPs = 5, unit_float = 5.1234, unit_string = "unit_5" }
[10:45:15.712827833] (+0.010001140) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 7 }, { vpid = 32764 }, { my_Time = "10:45:15", PID = 32764, OnePs = 63, TenPs = 6, HundredPs = 6, unit_float = 6.1234, unit_string = "unit_6" }
[10:45:15.722829191] (+0.010001358) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 7 }, { vpid = 32764 }, { my_Time = "10:45:15", PID = 32764, OnePs = 63, TenPs = 6, HundredPs = 7, unit_float = 7.1234, unit_string = "unit_7" }
[10:45:15.732830109] (+0.010000918) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 7 }, { vpid = 32764 }, { my_Time = "10:45:15", PID = 32764, OnePs = 63, TenPs = 6, HundredPs = 8, unit_float = 8.1234, unit_string = "unit_8" }
[10:45:15.742829510] (+0.009999401) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 7 }, { vpid = 32764 }, { my_Time = "10:45:15", PID = 32764, OnePs = 63, TenPs = 6, HundredPs = 9, unit_float = 9.1234, unit_string = "unit_9" }
[SC-1:Node16 Fri Apr 05 10:45:52/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:45:53/cluster/temp/log] # dir /cluster/dumps
total 0
[SC-1:Node16 Fri Apr 05 10:45:53/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:45:58/cluster/temp/log] # echo "Killing TestApp" >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:45:58/cluster/temp/log] # ps -e |grep -c TestApp
8000
[SC-1:Node16 Fri Apr 05 10:45:59/cluster/temp/log] # pkill TestApp
[SC-1:Node16 Fri Apr 05 10:46:04/cluster/temp/log] # echo "Killing Done ." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:46:04/cluster/temp/log] # ps -e |grep -c TestApp
0
[SC-1:Node16 Fri Apr 05 10:46:04/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:46:09/cluster/temp/log] # pkill sar
[SC-1:Node16 Fri Apr 05 10:46:09/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:46:09/cluster/temp/log] # cat $TC.load.log
Linux 3.0.42-0.7.3.4775.1.PTF-default (SC-1) 04/05/13 _x86_64_

10:44:06 CPU %user %nice %system %iowait %steal %idle
10:44:07 all 0.08 0.00 0.33 0.00 0.00 99.58
Start to launch apps when no session is active.
10:44:08 all 8.57 0.00 9.16 0.42 0.00 81.85
10:44:09 all 9.36 0.00 10.75 0.00 0.00 79.90
10:44:10 all 11.33 0.00 11.60 0.00 0.00 77.07
10:44:11 all 12.58 0.00 13.63 0.00 0.00 73.79
10:44:12 all 13.95 0.00 14.30 0.00 0.00 71.76
10:44:13 all 14.56 0.00 16.05 0.00 0.00 69.39
10:44:14 all 16.27 0.00 18.37 0.00 0.00 65.35
10:44:15 all 16.43 0.00 19.41 0.00 0.00 64.16
10:44:16 all 18.28 0.00 20.36 0.00 0.00 61.35
10:44:17 all 18.94 0.00 24.06 0.00 0.00 57.00
10:44:18 all 19.90 0.00 23.81 0.00 0.00 56.29
10:44:19 all 21.19 0.00 24.51 0.00 0.00 54.30
10:44:20 all 20.98 0.00 27.81 0.00 0.00 51.21
10:44:21 all 22.34 0.00 26.76 0.00 0.00 50.89
10:44:22 all 23.66 0.00 27.06 0.00 0.00 49.28
10:44:23 all 24.42 0.00 29.41 0.09 0.00 46.09
10:44:24 all 26.98 0.00 27.15 0.00 0.00 45.87
10:44:25 all 25.06 0.00 30.74 0.00 0.00 44.20
10:44:26 all 28.13 0.00 30.79 0.00 0.00 41.08
10:44:27 all 27.34 0.00 31.69 0.00 0.00 40.97
10:44:28 all 29.13 0.00 30.57 0.00 0.00 40.30
10:44:29 all 28.79 0.00 32.82 0.00 0.00 38.39
10:44:30 all 30.14 0.00 31.92 0.00 0.00 37.95
10:44:31 all 28.01 0.00 33.10 0.00 0.00 38.89
10:44:32 all 30.53 0.00 33.91 0.00 0.00 35.56
10:44:33 all 31.44 0.00 33.66 0.00 0.00 34.90
10:44:34 all 29.21 0.00 34.39 0.00 0.00 36.40
10:44:35 all 32.12 0.00 34.72 0.00 0.00 33.16
End of launching apps when no session is active
10:44:36 all 32.84 0.00 36.46 0.25 0.00 30.45
10:44:37 all 29.85 0.00 35.64 0.08 0.00 34.43
10:44:38 all 31.17 0.00 32.59 0.00 0.00 36.23
10:44:39 all 30.12 0.00 37.41 0.00 0.00 32.47
10:44:40 all 29.56 0.00 31.57 0.00 0.00 38.88
10:44:41 all 29.64 0.00 31.66 0.00 0.00 38.69
10:44:42 all 31.66 0.00 30.39 0.00 0.00 37.95
10:44:43 all 27.32 0.00 33.20 0.00 0.00 39.48
10:44:44 all 28.44 0.00 30.72 0.00 0.00 40.84
10:44:45 all 28.87 0.00 30.77 0.00 0.00 40.36
10:44:46 all 29.87 0.00 28.85 0.00 0.00 41.28
10:44:47 all 28.10 0.00 28.55 0.00 0.00 43.35
10:44:48 all 28.51 0.00 33.98 0.00 0.00 37.51
10:44:49 all 31.46 0.00 30.36 0.00 0.00 38.18
Create the session.
10:44:50 all 27.80 0.00 34.27 0.17 0.00 37.76
10:44:51 all 26.98 0.00 33.86 0.00 0.00 39.16
10:44:52 all 31.19 0.00 26.67 0.00 0.00 42.14
10:44:53 all 28.43 0.00 30.87 0.00 0.00 40.71
10:44:54 all 30.01 0.00 32.73 0.00 0.00 37.26
Enable channel....
10:44:55 all 27.54 0.00 34.59 0.48 0.00 37.39
10:44:56 all 31.45 0.00 34.07 0.00 0.00 34.49
10:44:57 all 30.94 0.00 36.85 0.00 0.00 32.21
10:44:58 all 30.97 0.00 37.29 0.00 0.00 31.75
10:44:59 all 30.87 0.00 35.88 0.00 0.00 33.25
10:45:00 all 30.94 0.00 38.67 0.00 0.00 30.39
10:45:01 all 29.97 0.00 35.95 0.00 0.00 34.07
10:45:02 all 29.08 0.00 36.17 0.00 0.00 34.75
10:45:03 all 31.14 0.00 36.24 0.00 0.00 32.62
Enable channel done.
Enable channel metadata....
Enable channel metadata done.
10:45:04 all 30.23 0.00 32.37 0.25 0.00 37.15
10:45:05 all 28.52 0.00 29.56 0.00 0.00 41.92
10:45:06 all 25.85 0.00 30.16 0.00 0.00 44.00
10:45:07 all 30.95 0.00 31.03 0.00 0.00 38.02
10:45:08 all 27.74 0.00 30.94 0.00 0.00 41.32
Enable Event....
10:45:09 all 29.60 0.00 31.73 0.18 0.00 38.49
10:45:10 all 32.10 0.00 36.39 0.00 0.00 31.52
Enable Event done.
10:45:11 all 27.34 0.00 32.36 0.17 0.00 40.13
10:45:12 all 29.11 0.00 32.24 0.00 0.00 38.65
10:45:13 all 27.81 0.00 35.81 0.00 0.00 36.38
10:45:14 all 28.49 0.00 33.67 0.00 0.00 37.83
10:45:15 all 31.60 0.00 31.45 0.00 0.00 36.95
Activate the session.
10:45:16 all 32.73 0.00 37.85 0.17 0.00 29.26
10:45:17 all 41.01 0.00 33.02 0.00 0.00 25.97
10:45:18 all 42.77 0.00 35.07 0.00 0.00 22.16
10:45:19 all 45.33 0.00 37.47 0.00 0.00 17.20
10:45:20 all 51.42 0.00 31.93 0.00 0.00 16.65
10:45:21 all 54.46 0.00 30.89 0.00 0.00 14.65
Activate session Done.
10:45:22 all 55.57 0.00 33.86 0.08 0.00 10.49
10:45:23 all 53.65 0.00 33.10 0.00 0.00 13.24
10:45:24 all 54.72 0.00 31.39 0.00 0.00 13.89
10:45:25 all 56.60 0.00 34.02 0.00 0.00 9.38
10:45:26 all 56.24 0.00 34.32 0.25 0.00 9.20
10:45:27 all 55.56 0.00 30.16 0.08 0.00 14.19
10:45:28 all 54.32 0.00 32.41 0.17 0.00 13.10
10:45:29 all 57.82 0.00 29.50 0.00 0.00 12.69
10:45:30 all 53.52 0.00 31.49 0.17 0.00 14.82
10:45:31 all 55.84 0.00 30.32 0.00 0.00 13.84
10:45:32 all 55.14 0.00 32.16 0.00 0.00 12.70
10:45:33 all 55.33 0.00 30.14 0.00 0.00 14.53
10:45:34 all 53.47 0.00 32.88 0.00 0.00 13.65
10:45:35 all 54.56 0.00 34.56 0.00 0.00 10.88
Stopping the session...
10:45:36 all 52.70 0.00 32.73 0.16 0.00 14.40
10:45:37 all 47.13 0.00 33.09 0.00 0.00 19.79
10:45:38 all 39.14 0.00 38.33 0.00 0.00 22.53
Stopping done.
10:45:39 all 30.79 0.00 31.85 0.16 0.00 37.20
10:45:40 all 31.02 0.00 29.73 0.00 0.00 39.26
10:45:41 all 30.39 0.00 34.41 0.00 0.00 35.20
10:45:42 all 30.14 0.00 30.06 0.00 0.00 39.81
10:45:43 all 31.18 0.00 28.72 0.08 0.00 40.02
10:45:44 all 30.97 0.00 33.28 0.00 0.00 35.75
Destroying the session...
10:45:45 all 29.57 0.00 32.14 0.09 0.00 38.21
10:45:46 all 32.23 0.00 35.54 0.00 0.00 32.23
Destroy done!
10:45:47 all 32.54 0.00 36.10 1.11 0.00 30.25
10:45:48 all 29.54 0.00 30.43 0.00 0.00 40.03
10:45:49 all 30.06 0.00 30.23 0.00 0.00 39.71
10:45:50 all 27.25 0.00 33.19 0.00 0.00 39.56
10:45:51 all 28.10 0.00 31.47 0.00 0.00 40.43
10:45:52 all 30.60 0.00 31.24 0.00 0.00 38.16
10:45:53 all 30.50 0.00 35.27 0.00 0.00 34.23
10:45:54 all 28.66 0.00 32.09 0.00 0.00 39.25
10:45:55 all 28.70 0.00 31.30 0.00 0.00 40.00
10:45:56 all 29.37 0.08 32.24 0.00 0.00 38.31
10:45:57 all 29.36 0.00 31.89 0.00 0.00 38.75
10:45:58 all 29.31 0.00 33.53 0.00 0.00 37.15
Killing TestApp
10:45:59 all 30.64 0.00 34.42 0.17 0.00 34.76
10:46:00 all 28.71 0.00 47.14 0.00 0.00 24.15
10:46:01 all 25.10 0.00 60.57 0.00 0.00 14.33
10:46:02 all 22.48 0.00 59.50 0.00 0.00 18.02
10:46:03 all 17.58 0.00 61.36 0.00 0.00 21.06
10:46:04 all 12.43 0.00 59.06 0.00 0.00 28.51
Killing Done .
10:46:05 all 0.84 0.00 9.76 0.50 0.00 88.90
10:46:06 all 0.00 0.00 0.08 0.00 0.00 99.92
10:46:07 all 0.00 0.00 0.08 0.00 0.00 99.92
10:46:08 all 0.00 0.00 0.17 0.00 0.00 99.83
10:46:09 all 0.00 0.00 0.08 0.00 0.00 99.92
[1]+ Terminated sar -u 1 300 >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:46:09/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:46:09/cluster/temp/log] # rm $TC.load.log
[SC-1:Node16 Fri Apr 05 10:46:09/cluster/temp/log] # babeltrace $TC | grep -c $DOMAIN_EVENT
2002
[SC-1:Node16 Fri Apr 05 10:46:09/cluster/temp/log] # du -h $TC | tail -n 1
388K LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run2
[SC-1:Node16 Fri Apr 05 10:46:09/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:47:15/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:47:15/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:47:15/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:47:15/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:47:15/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:47:16/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:47:16/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:47:16/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:47:16/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:47:16/cluster/temp/log] # export TC=LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run3
[SC-1:Node16 Fri Apr 05 10:47:18/cluster/temp/log] # DOMAIN_EVENT="com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec"
[SC-1:Node16 Fri Apr 05 10:47:18/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:47:18/cluster/temp/log] # sleep 1
sar -u 1 300 >> $TC.load.log &
netstat -etanp | head -n 2 ; netstat -etanp |egrep 'lttng'
sleep 1
echo "Start to launch apps when no session is active." >> $TC.load.log
#----------------------------------------------------------------------
date; time for n in $(seq 1 8000); do (/home/test_apps/TestApp_100psOnly 200 np &); done
#----------------------------------------------------------------------
echo "End of launching apps when no session is active" >> $TC.load.log
ps -ef |grep -c TestApp
sleep 1

#---------------------------- Get PID to trace on --------------------------------------------------
export my_pid=$(ps -e |grep TestApp | tail -n 1 | awk {'print $1'}); echo $my_pid
sleep 10

ps -ef |egrep 'lttng'
lttng-relayd -C tcp://0.0.0.0:53000 -D tcp://0.0.0.0:53001 -o /cluster/temp/log/$TC &
echo "Create the session." >> $TC.load.log
date; lttng create $TC -U net://192.168.0.1:53000:53001/./
lttng list
sleep 5
echo "Enable channel...." >> $TC.load.log
date; lttng enable-channel chan1 -u -s $TC --buffers-uid --subbuf-size 16384 --switch-timer 1000000
echo "Enable channel done." >> $TC.load.log
echo "Enable channel metadata...." >> $TC.load.log
date; lttng enable-channel metadata -u -s $TC --buffers-uid --subbuf-size 16384 --switch-timer 1000000
echo "Enable channel metadata done." >> $TC.load.log
sleep 5
lttng add-context -t vpid -u -s $TC
echo "Enable Event...." >> $TC.load.log
date; lttng enable-event -s $TC -u -c chan1 $DOMAIN_EVENT --filter "PID == $my_pid"
echo "Enable Event done." >> $TC.load.log
sleep 5

echo "Activate the session." >> $TC.load.log
#---------------------------------------------------- activate session -----------------------
date; lttng start;
echo "Activate session Done." >> $TC.load.log
sleep 1
lttng list $TC
sleep 1
ps -e |grep -c TestApp
dir -R $TC/SC-1/ust/uid/0/64-bit
sleep 1
dir -R $TC/SC-1/ust/uid/0/64-bit
sleep 1
dir -R $TC/SC-1/ust/uid/0/64-bit
sleep 1
dir -R $TC/SC-1/ust/uid/0/64-bit
sleep 1
dir -R $TC/SC-1/ust/uid/0/64-bit
sleep 5
dir -R $TC/SC-1/ust/uid/0/64-bit
echo "Stopping the session..." >> $TC.load.log
#---------------------------------------------------- De-activate session -----------------------
lttng stop
echo "Stopping done." >> $TC.load.log
sleep 1
dir -R $TC/SC-1/ust/uid/0/64-bit
sleep 5
echo "Destroying the session..." >> $TC.load.log
lttng destroy
echo "Destroy done! " >> $TC.load.log
sleep 5
dir -R $TC/SC-1/ust/uid/0/64-bit
pkill relayd

babeltrace $TC | head -n 10
sleep 1
dir /cluster/dumps
sleep 5
echo "Killing TestApp" >> $TC.load.log
ps -e |grep -c TestApp
pkill TestApp
echo "Killing Done ." >> $TC.load.log
ps -e |grep -c TestApp
sleep 5
pkill sar

cat $TC.load.log

rm $TC.load.log
babeltrace $TC | grep -c $DOMAIN_EVENT
du -h $TC | tail -n 1
[SC-1:Node16 Fri Apr 05 10:47:19/cluster/temp/log] # sar -u 1 300 >> $TC.load.log &
[1] 24639
[SC-1:Node16 Fri Apr 05 10:47:19/cluster/temp/log] # netstat -etanp | head -n 2 ; netstat -etanp |egrep 'lttng'
Active Internet connections (servers and established)
Proto Recv-Q Send-Q Local Address Foreign Address State User Inode PID/Program name
[SC-1:Node16 Fri Apr 05 10:47:19/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:47:20/cluster/temp/log] # echo "Start to launch apps when no session is active." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:47:20/cluster/temp/log] # #----------------------------------------------------------------------
[SC-1:Node16 Fri Apr 05 10:47:20/cluster/temp/log] # date; time for n in $(seq 1 8000); do (/home/test_apps/TestApp_100psOnly 200 np &); done
Fri Apr 5 10:47:20 EDT 2013

real 0m29.330s
user 0m3.392s
sys 0m1.600s
[SC-1:Node16 Fri Apr 05 10:47:49/cluster/temp/log] # #----------------------------------------------------------------------
[SC-1:Node16 Fri Apr 05 10:47:49/cluster/temp/log] # echo "End of launching apps when no session is active" >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:47:49/cluster/temp/log] # ps -ef |grep -c TestApp
8001
[SC-1:Node16 Fri Apr 05 10:47:50/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:47:51/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:47:51/cluster/temp/log] # #---------------------------- Get PID to trace on --------------------------------------------------
[SC-1:Node16 Fri Apr 05 10:47:51/cluster/temp/log] # export my_pid=$(ps -e |grep TestApp | tail -n 1 | awk {'print $1'}); echo $my_pid
32766
[SC-1:Node16 Fri Apr 05 10:47:52/cluster/temp/log] # sleep 10
[SC-1:Node16 Fri Apr 05 10:48:02/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:48:02/cluster/temp/log] # ps -ef |egrep 'lttng'
root 13798 1 0 Apr03 ? 00:02:52 lttng-sessiond -d
root 24530 4536 0 10:48 pts/1 00:00:00 egrep lttng
root 24531 13787 0 10:48 ? 00:00:00 /bin/bash /opt/trace_ea/bin/lttng-proxy start
root 24532 24531 0 10:48 ? 00:00:00 pgrep lttng-sessiond
root 31628 13798 0 Apr03 ? 00:01:45 lttng-consumerd --quiet -u --consumerd-cmd-sock /var/run/lttng/ustconsumerd64/command --consumerd-err-sock /var/run/lttng/ustconsumerd64/error
[SC-1:Node16 Fri Apr 05 10:48:03/cluster/temp/log] # lttng-relayd -C tcp://0.0.0.0:53000 -D tcp://0.0.0.0:53001 -o /cluster/temp/log/$TC &
[2] 24533
[SC-1:Node16 Fri Apr 05 10:48:03/cluster/temp/log] # echo "Create the session." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:48:03/cluster/temp/log] # date; lttng create $TC -U net://192.168.0.1:53000:53001/./
Fri Apr 5 10:48:03 EDT 2013
Session LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run3 created.
Traces will be written in net://192.168.0.1:53000:53001/./
[SC-1:Node16 Fri Apr 05 10:48:03/cluster/temp/log] # lttng list
Available tracing sessions:
1) LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run3 (net://192.168.0.1:53000/./ [data: 5343]) [inactive]

Use lttng list <session_name> for more details
[SC-1:Node16 Fri Apr 05 10:48:03/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:48:08/cluster/temp/log] # echo "Enable channel...." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:48:08/cluster/temp/log] # date; lttng enable-channel chan1 -u -s $TC --buffers-uid --subbuf-size 16384 --switch-timer 1000000
Fri Apr 5 10:48:08 EDT 2013
UST channel chan1 enabled for session LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run3
[SC-1:Node16 Fri Apr 05 10:48:16/cluster/temp/log] # echo "Enable channel done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:48:16/cluster/temp/log] # echo "Enable channel metadata...." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:48:16/cluster/temp/log] # date; lttng enable-channel metadata -u -s $TC --buffers-uid --subbuf-size 16384 --switch-timer 1000000
Fri Apr 5 10:48:16 EDT 2013
UST channel metadata enabled for session LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run3
[SC-1:Node16 Fri Apr 05 10:48:16/cluster/temp/log] # echo "Enable channel metadata done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:48:16/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:48:21/cluster/temp/log] # lttng add-context -t vpid -u -s $TC
UST context vpid added to all channels
[SC-1:Node16 Fri Apr 05 10:48:22/cluster/temp/log] # echo "Enable Event...." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:48:22/cluster/temp/log] # date; lttng enable-event -s $TC -u -c chan1 $DOMAIN_EVENT --filter "PID == $my_pid"
Fri Apr 5 10:48:22 EDT 2013
Filter 'PID == 32766' successfully set
[SC-1:Node16 Fri Apr 05 10:48:23/cluster/temp/log] # echo "Enable Event done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:48:23/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:48:28/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:48:28/cluster/temp/log] # echo "Activate the session." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:48:28/cluster/temp/log] # #---------------------------------------------------- activate session -----------------------
[SC-1:Node16 Fri Apr 05 10:48:28/cluster/temp/log] # date; lttng start;
Fri Apr 5 10:48:28 EDT 2013
Tracing started for session LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run3
[SC-1:Node16 Fri Apr 05 10:48:34/cluster/temp/log] # echo "Activate session Done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:48:34/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:48:35/cluster/temp/log] # lttng list $TC
Tracing session LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run3: [active]
Trace path: net://192.168.0.1:53000/./ [data: 53001]

=== Domain: UST global ===

Channels:
-------------
- metadata: [enabled]

Attributes:
overwrite mode: 0
subbufers size: 16384
number of subbufers: 4
switch timer interval: 1000000
read timer interval: 200000
output: mmap()

Events:
None

- chan1: [enabled]

Attributes:
overwrite mode: 0
subbufers size: 16384
number of subbufers: 4
switch timer interval: 1000000
read timer interval: 200000
output: mmap()

Events:
com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec (type: tracepoint) [enabled] [with filter]

[SC-1:Node16 Fri Apr 05 10:48:35/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:48:36/cluster/temp/log] # ps -e |grep -c TestApp
8000
[SC-1:Node16 Fri Apr 05 10:48:37/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run3/SC-1/ust/uid/0/64-bit:
total 92
-rw-rw---- 1 root root 12288 Apr 5 10:48 metadata
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_9
-rw-rw---- 1 root root 36864 Apr 5 10:48 chan1_6
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_11
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_8
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_7
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_5
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_4
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_3
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_2
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_10
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_1
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_0
[SC-1:Node16 Fri Apr 05 10:48:38/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:48:39/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run3/SC-1/ust/uid/0/64-bit:
total 100
-rw-rw---- 1 root root 12288 Apr 5 10:48 metadata
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_9
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_11
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_8
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_7
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_5
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_4
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_3
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_2
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_10
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_1
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_0
-rw-rw---- 1 root root 45056 Apr 5 10:48 chan1_6
[SC-1:Node16 Fri Apr 05 10:48:39/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:48:40/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run3/SC-1/ust/uid/0/64-bit:
total 112
-rw-rw---- 1 root root 12288 Apr 5 10:48 metadata
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_9
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_11
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_8
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_7
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_5
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_4
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_3
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_2
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_10
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_1
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_0
-rw-rw---- 1 root root 53248 Apr 5 10:48 chan1_6
[SC-1:Node16 Fri Apr 05 10:48:40/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:48:41/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run3/SC-1/ust/uid/0/64-bit:
total 120
-rw-rw---- 1 root root 12288 Apr 5 10:48 metadata
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_9
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_11
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_8
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_7
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_5
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_4
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_3
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_2
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_10
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_1
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_0
-rw-rw---- 1 root root 61440 Apr 5 10:48 chan1_6
[SC-1:Node16 Fri Apr 05 10:48:41/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:48:42/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run3/SC-1/ust/uid/0/64-bit:
total 132
-rw-rw---- 1 root root 12288 Apr 5 10:48 metadata
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_9
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_11
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_8
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_7
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_5
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_4
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_3
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_2
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_10
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_1
-rw-rw---- 1 root root 69632 Apr 5 10:48 chan1_6
-rw-rw---- 1 root root 8192 Apr 5 10:48 chan1_0
[SC-1:Node16 Fri Apr 05 10:48:42/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:48:47/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run3/SC-1/ust/uid/0/64-bit:
total 180
-rw-rw---- 1 root root 12288 Apr 5 10:48 metadata
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_9
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_11
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_7
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_5
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_4
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_3
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_10
-rw-rw---- 1 root root 69632 Apr 5 10:48 chan1_6
-rw-rw---- 1 root root 8192 Apr 5 10:48 chan1_2
-rw-rw---- 1 root root 8192 Apr 5 10:48 chan1_1
-rw-rw---- 1 root root 12288 Apr 5 10:48 chan1_0
-rw-rw---- 1 root root 40960 Apr 5 10:48 chan1_8
[SC-1:Node16 Fri Apr 05 10:48:47/cluster/temp/log] # echo "Stopping the session..." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:48:47/cluster/temp/log] # #---------------------------------------------------- De-activate session -----------------------
[SC-1:Node16 Fri Apr 05 10:48:47/cluster/temp/log] # lttng stop
Waiting for data availability
Tracing stopped for session LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run3
[SC-1:Node16 Fri Apr 05 10:48:50/cluster/temp/log] # echo "Stopping done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:48:50/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:48:51/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run3/SC-1/ust/uid/0/64-bit:
total 1400
-rw-rw---- 1 root root 12288 Apr 5 10:48 metadata
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_11
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_7
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_5
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_4
-rw-rw---- 1 root root 4096 Apr 5 10:48 chan1_10
-rw-rw---- 1 root root 69632 Apr 5 10:48 chan1_6
-rw-rw---- 1 root root 8192 Apr 5 10:48 chan1_1
-rw-rw---- 1 root root 12288 Apr 5 10:48 chan1_0
-rw-rw---- 1 root root 253952 Apr 5 10:48 chan1_9
-rw-rw---- 1 root root 561152 Apr 5 10:48 chan1_8
-rw-rw---- 1 root root 405504 Apr 5 10:48 chan1_3
-rw-rw---- 1 root root 69632 Apr 5 10:48 chan1_2
[SC-1:Node16 Fri Apr 05 10:48:51/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:48:56/cluster/temp/log] # echo "Destroying the session..." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:48:56/cluster/temp/log] # lttng destroy
Session LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run3 destroyed
[SC-1:Node16 Fri Apr 05 10:48:58/cluster/temp/log] # echo "Destroy done! " >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:48:58/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:49:03/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run3/SC-1/ust/uid/0/64-bit:
total 1452
-rw-rw---- 1 root root 16384 Apr 5 10:48 metadata
-rw-rw---- 1 root root 258048 Apr 5 10:48 chan1_9
-rw-rw---- 1 root root 565248 Apr 5 10:48 chan1_8
-rw-rw---- 1 root root 73728 Apr 5 10:48 chan1_6
-rw-rw---- 1 root root 8192 Apr 5 10:48 chan1_5
-rw-rw---- 1 root root 8192 Apr 5 10:48 chan1_4
-rw-rw---- 1 root root 409600 Apr 5 10:48 chan1_3
-rw-rw---- 1 root root 73728 Apr 5 10:48 chan1_2
-rw-rw---- 1 root root 8192 Apr 5 10:48 chan1_11
-rw-rw---- 1 root root 8192 Apr 5 10:48 chan1_10
-rw-rw---- 1 root root 12288 Apr 5 10:48 chan1_1
-rw-rw---- 1 root root 16384 Apr 5 10:48 chan1_0
-rw-rw---- 1 root root 8192 Apr 5 10:48 chan1_7
[SC-1:Node16 Fri Apr 05 10:49:03/cluster/temp/log] # pkill relayd
[2]+ Done lttng-relayd -C tcp://0.0.0.0:53000 -D tcp://0.0.0.0:53001 -o /cluster/temp/log/$TC
[SC-1:Node16 Fri Apr 05 10:49:04/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:49:04/cluster/temp/log] # babeltrace $TC | head -n 10
[10:48:33.608198553] (+?.?????????) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 6 }, { vpid = 32766 }, { my_Time = "10:48:33", PID = 32766, OnePs = 69, TenPs = 5, HundredPs = 6, unit_float = 6.1234, unit_string = "unit_6" }
[10:48:33.618203067] (+0.010004514) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 6 }, { vpid = 32766 }, { my_Time = "10:48:33", PID = 32766, OnePs = 69, TenPs = 5, HundredPs = 7, unit_float = 7.1234, unit_string = "unit_7" }
[10:48:33.628140994] (+0.009937927) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 6 }, { vpid = 32766 }, { my_Time = "10:48:33", PID = 32766, OnePs = 69, TenPs = 5, HundredPs = 8, unit_float = 8.1234, unit_string = "unit_8" }
[10:48:33.638139721] (+0.009998727) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 6 }, { vpid = 32766 }, { my_Time = "10:48:33", PID = 32766, OnePs = 69, TenPs = 5, HundredPs = 9, unit_float = 9.1234, unit_string = "unit_9" }
[10:48:33.648140799] (+0.010001078) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 6 }, { vpid = 32766 }, { my_Time = "10:48:33", PID = 32766, OnePs = 69, TenPs = 6, HundredPs = 0, unit_float = 0.1234, unit_string = "unit_0" }
[10:48:33.658139517] (+0.009998718) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 6 }, { vpid = 32766 }, { my_Time = "10:48:33", PID = 32766, OnePs = 69, TenPs = 6, HundredPs = 1, unit_float = 1.1234, unit_string = "unit_1" }
[10:48:33.668141455] (+0.010001938) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 6 }, { vpid = 32766 }, { my_Time = "10:48:33", PID = 32766, OnePs = 69, TenPs = 6, HundredPs = 2, unit_float = 2.1234, unit_string = "unit_2" }
[10:48:33.678139931] (+0.009998476) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 6 }, { vpid = 32766 }, { my_Time = "10:48:33", PID = 32766, OnePs = 69, TenPs = 6, HundredPs = 3, unit_float = 3.1234, unit_string = "unit_3" }
[10:48:33.688139565] (+0.009999634) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 6 }, { vpid = 32766 }, { my_Time = "10:48:33", PID = 32766, OnePs = 69, TenPs = 6, HundredPs = 4, unit_float = 4.1234, unit_string = "unit_4" }
[10:48:33.698140982] (+0.010001417) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 6 }, { vpid = 32766 }, { my_Time = "10:48:33", PID = 32766, OnePs = 69, TenPs = 6, HundredPs = 5, unit_float = 5.1234, unit_string = "unit_5" }
[SC-1:Node16 Fri Apr 05 10:49:04/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:49:05/cluster/temp/log] # dir /cluster/dumps
total 0
[SC-1:Node16 Fri Apr 05 10:49:05/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:49:10/cluster/temp/log] # echo "Killing TestApp" >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:49:10/cluster/temp/log] # ps -e |grep -c TestApp
8000
[SC-1:Node16 Fri Apr 05 10:49:11/cluster/temp/log] # pkill TestApp
[SC-1:Node16 Fri Apr 05 10:49:17/cluster/temp/log] # echo "Killing Done ." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:49:17/cluster/temp/log] # ps -e |grep -c TestApp
0
[SC-1:Node16 Fri Apr 05 10:49:17/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:49:22/cluster/temp/log] # pkill sar
[SC-1:Node16 Fri Apr 05 10:49:22/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:49:22/cluster/temp/log] # cat $TC.load.log
Linux 3.0.42-0.7.3.4775.1.PTF-default (SC-1) 04/05/13 _x86_64_

10:47:19 CPU %user %nice %system %iowait %steal %idle
10:47:20 all 0.17 0.00 0.25 0.00 0.00 99.58
Start to launch apps when no session is active.
10:47:21 all 8.40 0.00 10.00 0.42 0.00 81.18
10:47:22 all 9.57 0.00 10.44 0.00 0.00 79.98
10:47:23 all 11.83 0.00 12.09 0.00 0.00 76.09
10:47:24 all 12.77 0.00 12.95 0.00 0.00 74.28
10:47:25 all 14.11 0.00 13.58 0.00 0.00 72.31
10:47:26 all 15.86 0.00 15.51 0.00 0.00 68.63
10:47:27 all 15.81 0.00 18.42 0.00 0.00 65.77
10:47:28 all 16.43 0.00 20.26 0.00 0.00 63.30
10:47:29 all 17.63 0.00 21.93 0.00 0.00 60.44
10:47:30 all 18.51 0.00 22.06 0.00 0.00 59.43
10:47:31 all 21.06 0.00 22.77 0.00 0.00 56.16
10:47:32 all 20.98 0.00 25.09 0.00 0.00 53.94
10:47:33 all 22.52 0.00 25.60 0.00 0.00 51.88
10:47:34 all 23.51 0.00 26.36 0.00 0.00 50.13
10:47:35 all 24.02 0.00 27.53 0.00 0.00 48.45
10:47:36 all 26.23 0.00 27.33 0.00 0.00 46.43
10:47:37 all 25.37 0.00 27.36 0.00 0.00 47.27
10:47:38 all 25.26 0.00 27.99 0.00 0.00 46.74
10:47:39 all 25.68 0.00 31.51 0.00 0.00 42.81
10:47:40 all 28.33 0.00 30.93 0.00 0.00 40.75
10:47:41 all 28.34 0.00 30.69 0.00 0.00 40.97
10:47:42 all 28.70 0.00 32.28 0.00 0.00 39.02
10:47:43 all 29.62 0.00 31.22 0.00 0.00 39.16
10:47:44 all 29.45 0.00 33.16 0.00 0.00 37.38
10:47:45 all 29.08 0.00 35.16 0.00 0.00 35.76
10:47:46 all 28.28 0.00 34.68 0.00 0.00 37.04
10:47:47 all 29.15 0.00 33.46 0.00 0.00 37.40
10:47:48 all 29.92 0.00 35.97 0.00 0.00 34.11
10:47:49 all 32.55 0.00 32.90 0.00 0.00 34.56
End of launching apps when no session is active
10:47:50 all 30.74 0.00 36.06 0.16 0.00 33.03
10:47:51 all 29.58 0.00 36.51 0.00 0.00 33.90
10:47:52 all 27.80 0.00 33.62 0.00 0.00 38.58
10:47:53 all 26.44 0.00 32.64 0.00 0.00 40.92
10:47:54 all 28.90 0.00 31.63 0.00 0.00 39.47
10:47:55 all 28.15 0.00 29.46 0.00 0.00 42.40
10:47:56 all 28.46 0.00 30.46 0.00 0.00 41.08
10:47:57 all 29.25 0.00 30.36 0.00 0.00 40.39
10:47:58 all 27.42 0.00 30.81 0.00 0.00 41.78
10:47:59 all 26.08 0.00 32.01 0.00 0.00 41.91
10:48:00 all 28.26 0.00 30.33 0.00 0.00 41.41
10:48:01 all 29.93 0.00 30.27 0.00 0.00 39.80
10:48:02 all 26.37 0.00 31.01 0.00 0.00 42.61
10:48:03 all 29.05 0.00 31.19 0.00 0.00 39.76
Create the session.
10:48:04 all 28.81 0.00 31.56 0.09 0.00 39.54
10:48:05 all 28.21 0.00 28.38 0.00 0.00 43.41
10:48:06 all 26.82 0.00 29.73 0.00 0.00 43.45
10:48:07 all 27.65 0.00 32.81 0.00 0.00 39.55
10:48:08 all 28.72 0.00 29.72 0.00 0.00 41.56
Enable channel....
10:48:09 all 29.59 0.00 31.80 0.34 0.00 38.27
10:48:10 all 30.48 0.00 36.44 0.00 0.00 33.07
10:48:11 all 30.83 0.00 33.28 0.00 0.00 35.90
10:48:12 all 29.21 0.00 34.40 0.00 0.00 36.39
10:48:13 all 29.13 0.00 37.68 0.00 0.00 33.19
10:48:14 all 30.87 0.00 33.19 0.00 0.00 35.94
10:48:15 all 29.30 0.00 35.10 0.00 0.00 35.60
10:48:16 all 31.20 0.00 37.36 0.00 0.00 31.44
Enable channel done.
Enable channel metadata....
Enable channel metadata done.
10:48:17 all 28.80 0.00 31.71 0.27 0.00 39.22
10:48:18 all 26.10 0.00 32.12 0.00 0.00 41.78
10:48:19 all 28.49 0.00 32.36 0.00 0.00 39.16
10:48:20 all 29.28 0.00 29.03 0.00 0.00 41.69
10:48:21 all 26.56 0.00 30.30 0.00 0.00 43.14
10:48:22 all 30.06 0.00 32.11 0.00 0.00 37.83
Enable Event....
10:48:23 all 32.72 0.00 32.21 0.17 0.00 34.90
Enable Event done.
10:48:24 all 30.68 0.00 29.59 0.17 0.00 39.56
10:48:25 all 28.63 0.00 31.28 0.00 0.00 40.09
10:48:26 all 28.79 0.00 28.87 0.00 0.00 42.34
10:48:27 all 28.41 0.00 29.27 0.00 0.00 42.32
10:48:28 all 29.59 0.00 32.34 0.00 0.00 38.08
Activate the session.
10:48:29 all 31.64 0.00 33.93 0.17 0.00 34.26
10:48:30 all 39.54 0.00 32.06 0.00 0.00 28.40
10:48:31 all 44.08 0.00 32.99 0.00 0.00 22.93
10:48:32 all 45.59 0.00 36.44 0.00 0.00 17.97
10:48:33 all 51.05 0.00 32.38 0.00 0.00 16.57
10:48:34 all 54.34 0.00 31.97 0.00 0.00 13.69
Activate session Done.
10:48:35 all 57.49 0.00 33.01 0.00 0.00 9.50
10:48:36 all 53.83 0.00 30.75 0.00 0.00 15.42
10:48:37 all 53.73 0.00 34.04 0.00 0.00 12.24
10:48:38 all 58.09 0.00 34.62 0.34 0.00 6.96
10:48:39 all 55.42 0.00 30.62 0.00 0.00 13.96
10:48:40 all 52.44 0.00 32.51 0.00 0.00 15.05
10:48:41 all 55.82 0.00 32.11 0.00 0.00 12.07
10:48:42 all 53.62 0.00 30.48 0.00 0.00 15.90
10:48:43 all 52.75 0.00 32.17 0.00 0.00 15.08
10:48:44 all 57.14 0.00 30.95 0.00 0.00 11.90
10:48:45 all 54.98 0.00 29.87 0.17 0.00 14.98
10:48:46 all 56.71 0.00 28.15 0.00 0.00 15.13
10:48:47 all 54.51 0.00 32.11 0.00 0.00 13.37
Stopping the session...
10:48:48 all 55.16 0.00 32.78 0.00 0.00 12.06
10:48:49 all 49.80 0.00 33.39 0.00 0.00 16.81
10:48:50 all 42.76 0.00 36.42 0.00 0.00 20.82
Stopping done.
10:48:51 all 32.35 0.00 33.23 0.16 0.00 34.26
10:48:52 all 28.67 0.00 31.73 0.00 0.00 39.60
10:48:53 all 29.74 0.00 33.84 0.00 0.00 36.41
10:48:54 all 27.19 0.00 31.65 0.00 0.00 41.16
10:48:55 all 27.42 0.00 31.12 0.08 0.00 41.38
10:48:56 all 29.76 0.00 31.99 0.00 0.00 38.25
Destroying the session...
10:48:57 all 27.95 0.00 34.09 0.08 0.00 37.88
10:48:58 all 29.29 0.00 34.32 0.00 0.00 36.40
Destroy done!
10:48:59 all 31.14 0.00 32.97 1.50 0.00 34.39
10:49:00 all 29.61 0.00 29.95 0.00 0.00 40.44
10:49:01 all 30.16 0.00 27.97 0.00 0.00 41.87
10:49:02 all 30.40 0.00 29.32 0.00 0.00 40.28
10:49:03 all 27.69 0.00 33.31 0.00 0.00 39.01
10:49:04 all 28.34 0.00 34.01 0.00 0.00 37.65
10:49:05 all 29.42 0.00 31.77 0.00 0.00 38.82
10:49:06 all 28.05 0.00 34.18 0.00 0.00 37.78
10:49:07 all 30.14 0.00 29.90 0.00 0.00 39.97
10:49:08 all 27.88 0.00 32.31 0.00 0.00 39.81
10:49:09 all 28.74 0.00 34.07 0.00 0.00 37.19
10:49:10 all 30.34 0.00 29.53 0.00 0.00 40.13
Killing TestApp
10:49:11 all 31.06 0.00 34.68 0.16 0.00 34.10
10:49:12 all 28.60 0.00 51.17 0.00 0.00 20.23
10:49:13 all 23.96 0.00 54.38 0.00 0.00 21.67
10:49:14 all 20.73 0.00 57.54 0.00 0.00 21.73
10:49:15 all 19.67 0.00 54.98 0.00 0.00 25.35
10:49:16 all 15.21 0.00 47.70 0.00 0.00 37.09
10:49:17 all 12.47 0.00 50.54 0.00 0.00 36.99
Killing Done .
10:49:18 all 2.95 0.00 26.54 0.42 0.00 70.09
10:49:19 all 0.00 0.00 0.17 0.00 0.00 99.83
10:49:20 all 0.08 0.00 0.00 0.00 0.00 99.92
10:49:21 all 0.00 0.00 0.25 0.00 0.00 99.75
10:49:22 all 0.00 0.00 0.00 0.00 0.00 100.00
[1]+ Terminated sar -u 1 300 >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:49:22/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:49:22/cluster/temp/log] # rm $TC.load.log
[SC-1:Node16 Fri Apr 05 10:49:22/cluster/temp/log] # babeltrace $TC | grep -c $DOMAIN_EVENT
1691
[SC-1:Node16 Fri Apr 05 10:49:22/cluster/temp/log] # du -h $TC | tail -n 1
1.5M LTTNGgbf_017_8kAppFirst_1s_Pid_buf16k_100ps_run3
[SC-1:Node16 Fri Apr 05 10:49:22/cluster/temp/log] #
(2-2/9)