Project

General

Profile

Download (97.9 KB)

Bug #497 » TC17_node16_8KAppFirst_noTimer_TraceOn1pid_buf16k_100ps_a_b_c.log

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

 
[SC-1:Node16 Fri Apr 05 10:00:03/cluster/temp/log] # export TC=LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run1
[SC-1:Node16 Fri Apr 05 10:00:22/cluster/temp/log] # DOMAIN_EVENT="com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec"
[SC-1:Node16 Fri Apr 05 10:00:22/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:00:22/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:00:23/cluster/temp/log] # sar -u 1 300 >> $TC.load.log &
[1] 24557
[SC-1:Node16 Fri Apr 05 10:00:23/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:00:23/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:00:24/cluster/temp/log] # echo "Start to launch apps when no session is active." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:00:24/cluster/temp/log] # #----------------------------------------------------------------------
[SC-1:Node16 Fri Apr 05 10:00:24/cluster/temp/log] # date; time for n in $(seq 1 8000); do (/home/test_apps/TestApp_100psOnly 200 np &); done
Fri Apr 5 10:00:24 EDT 2013

real 0m26.725s
user 0m2.796s
sys 0m1.560s
[SC-1:Node16 Fri Apr 05 10:00:51/cluster/temp/log] # #----------------------------------------------------------------------
[SC-1:Node16 Fri Apr 05 10:00:51/cluster/temp/log] # echo "End of launching apps when no session is active" >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:00:51/cluster/temp/log] # ps -ef |grep -c TestApp
8001
[SC-1:Node16 Fri Apr 05 10:00:52/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:00:53/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:00:53/cluster/temp/log] # #---------------------------- Get PID to trace on --------------------------------------------------
[SC-1:Node16 Fri Apr 05 10:00:53/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:00:54/cluster/temp/log] # sleep 10
[SC-1:Node16 Fri Apr 05 10:01:04/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:01:04/cluster/temp/log] # ps -ef |egrep 'lttng'
root 13798 1 0 Apr03 ? 00:02:17 lttng-sessiond -d
root 24448 4536 0 10:01 pts/1 00:00:00 egrep lttng
root 24449 13787 0 10:01 ? 00:00:00 /bin/bash /opt/trace_ea/bin/lttng-proxy start
root 24450 24449 0 10:01 ? 00:00:00 pgrep lttng-sessiond
root 31628 13798 0 Apr03 ? 00:01:37 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:01:05/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] 24451
[SC-1:Node16 Fri Apr 05 10:01:05/cluster/temp/log] # echo "Create the session." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:01:05/cluster/temp/log] # date; lttng create $TC -U net://192.168.0.1:53000:53001/./
Fri Apr 5 10:01:05 EDT 2013
Session LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run1 created.
Traces will be written in net://192.168.0.1:53000:53001/./
[SC-1:Node16 Fri Apr 05 10:01:05/cluster/temp/log] # lttng list
Available tracing sessions:
1) LTTNGgbf_017_8kAppFirst_NoTimer_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:01:05/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:01:10/cluster/temp/log] # echo "Enable channel...." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:01:10/cluster/temp/log] # date; lttng enable-channel chan1 -u -s $TC --buffers-uid --subbuf-size 16384 #--switch-timer 1000000
Fri Apr 5 10:01:10 EDT 2013
UST channel chan1 enabled for session LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run1
[SC-1:Node16 Fri Apr 05 10:01:18/cluster/temp/log] # echo "Enable channel done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:01:18/cluster/temp/log] # echo "Enable channel metadata...." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:01:18/cluster/temp/log] # date; lttng enable-channel metadata -u -s $TC --buffers-uid --subbuf-size 16384 #--switch-timer 1000000
Fri Apr 5 10:01:18 EDT 2013
UST channel metadata enabled for session LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run1
[SC-1:Node16 Fri Apr 05 10:01:18/cluster/temp/log] # echo "Enable channel metadata done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:01:18/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:01:23/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:01:24/cluster/temp/log] # echo "Enable Event...." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:01:24/cluster/temp/log] # date; lttng enable-event -s $TC -u -c chan1 $DOMAIN_EVENT --filter "PID == $my_pid"
Fri Apr 5 10:01:24 EDT 2013
Filter 'PID == 32766' successfully set
[SC-1:Node16 Fri Apr 05 10:01:25/cluster/temp/log] # echo "Enable Event done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:01:25/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:01:30/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:01:30/cluster/temp/log] # echo "Activate the session." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:01:30/cluster/temp/log] # #---------------------------------------------------- activate session -----------------------
[SC-1:Node16 Fri Apr 05 10:01:30/cluster/temp/log] # date; lttng start;
Fri Apr 5 10:01:30 EDT 2013
Tracing started for session LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run1
[SC-1:Node16 Fri Apr 05 10:01:35/cluster/temp/log] # echo "Activate session Done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:01:35/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:01:36/cluster/temp/log] # lttng list $TC
Tracing session LTTNGgbf_017_8kAppFirst_NoTimer_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: 0
read timer interval: 200000
output: mmap()

Events:
None

- chan1: [enabled]

Attributes:
overwrite mode: 0
subbufers size: 16384
number of subbufers: 4
switch timer interval: 0
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:01:36/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:01:37/cluster/temp/log] # ps -e |grep -c TestApp
8000
[SC-1:Node16 Fri Apr 05 10:01:39/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run1/SC-1/ust/uid/0/64-bit:
total 0
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_9
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_8
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_7
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_6
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_5
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_4
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_3
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_2
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_11
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_10
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_1
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_0
-rw-rw---- 1 root root 0 Apr 5 10:01 metadata
[SC-1:Node16 Fri Apr 05 10:01:39/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:01:40/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run1/SC-1/ust/uid/0/64-bit:
total 0
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_9
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_8
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_7
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_6
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_5
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_4
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_3
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_2
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_11
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_10
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_1
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_0
-rw-rw---- 1 root root 0 Apr 5 10:01 metadata
[SC-1:Node16 Fri Apr 05 10:01:40/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:01:41/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run1/SC-1/ust/uid/0/64-bit:
total 0
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_9
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_8
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_7
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_6
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_5
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_4
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_3
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_2
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_11
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_10
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_1
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_0
-rw-rw---- 1 root root 0 Apr 5 10:01 metadata
[SC-1:Node16 Fri Apr 05 10:01:41/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:01:42/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run1/SC-1/ust/uid/0/64-bit:
total 0
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_9
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_8
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_7
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_6
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_5
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_4
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_3
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_2
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_11
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_10
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_1
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_0
-rw-rw---- 1 root root 0 Apr 5 10:01 metadata
[SC-1:Node16 Fri Apr 05 10:01:42/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:01:43/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run1/SC-1/ust/uid/0/64-bit:
total 0
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_9
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_8
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_7
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_6
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_5
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_4
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_3
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_2
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_11
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_10
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_1
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_0
-rw-rw---- 1 root root 0 Apr 5 10:01 metadata
[SC-1:Node16 Fri Apr 05 10:01:43/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:01:48/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run1/SC-1/ust/uid/0/64-bit:
total 16
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_9
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_8
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_7
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_6
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_5
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_4
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_3
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_2
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_11
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_1
-rw-rw---- 1 root root 0 Apr 5 10:01 chan1_0
-rw-rw---- 1 root root 0 Apr 5 10:01 metadata
-rw-rw---- 1 root root 16384 Apr 5 10:01 chan1_10
[SC-1:Node16 Fri Apr 05 10:01:48/cluster/temp/log] # echo "Stopping the session..." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:01:48/cluster/temp/log] # #---------------------------------------------------- De-activate session -----------------------
[SC-1:Node16 Fri Apr 05 10:01:48/cluster/temp/log] # lttng stop
Waiting for data availability
Tracing stopped for session LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run1
[SC-1:Node16 Fri Apr 05 10:01:51/cluster/temp/log] # echo "Stopping done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:01:51/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:01:52/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run1/SC-1/ust/uid/0/64-bit:
total 1256
-rw-rw---- 1 root root 4096 Apr 5 10:01 metadata
-rw-rw---- 1 root root 352256 Apr 5 10:01 chan1_9
-rw-rw---- 1 root root 4096 Apr 5 10:01 chan1_8
-rw-rw---- 1 root root 16384 Apr 5 10:01 chan1_7
-rw-rw---- 1 root root 4096 Apr 5 10:01 chan1_6
-rw-rw---- 1 root root 16384 Apr 5 10:01 chan1_5
-rw-rw---- 1 root root 81920 Apr 5 10:01 chan1_4
-rw-rw---- 1 root root 65536 Apr 5 10:01 chan1_3
-rw-rw---- 1 root root 94208 Apr 5 10:01 chan1_2
-rw-rw---- 1 root root 4096 Apr 5 10:01 chan1_11
-rw-rw---- 1 root root 610304 Apr 5 10:01 chan1_10
-rw-rw---- 1 root root 8192 Apr 5 10:01 chan1_1
-rw-rw---- 1 root root 4096 Apr 5 10:01 chan1_0
[SC-1:Node16 Fri Apr 05 10:01:52/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:01:57/cluster/temp/log] # echo "Destroying the session..." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:01:57/cluster/temp/log] # lttng destroy
Session LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run1 destroyed
[SC-1:Node16 Fri Apr 05 10:02:00/cluster/temp/log] # echo "Destroy done! " >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:02:00/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:02:05/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run1/SC-1/ust/uid/0/64-bit:
total 1308
-rw-rw---- 1 root root 8192 Apr 5 10:02 metadata
-rw-rw---- 1 root root 356352 Apr 5 10:02 chan1_9
-rw-rw---- 1 root root 8192 Apr 5 10:02 chan1_8
-rw-rw---- 1 root root 20480 Apr 5 10:02 chan1_7
-rw-rw---- 1 root root 8192 Apr 5 10:02 chan1_6
-rw-rw---- 1 root root 20480 Apr 5 10:02 chan1_5
-rw-rw---- 1 root root 86016 Apr 5 10:02 chan1_4
-rw-rw---- 1 root root 69632 Apr 5 10:02 chan1_3
-rw-rw---- 1 root root 98304 Apr 5 10:02 chan1_2
-rw-rw---- 1 root root 8192 Apr 5 10:02 chan1_11
-rw-rw---- 1 root root 614400 Apr 5 10:02 chan1_10
-rw-rw---- 1 root root 12288 Apr 5 10:02 chan1_1
-rw-rw---- 1 root root 8192 Apr 5 10:02 chan1_0
[SC-1:Node16 Fri Apr 05 10:02:05/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:02:05/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:02:05/cluster/temp/log] # babeltrace $TC | head -n 10
[10:01:35.038563175] (+?.?????????) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 5 }, { vpid = 32766 }, { my_Time = "10:01:34", PID = 32766, OnePs = 65, TenPs = 9, HundredPs = 9, unit_float = 9.1234, unit_string = "unit_9" }
[10:01:35.048642537] (+0.010079362) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 5 }, { vpid = 32766 }, { my_Time = "10:01:35", PID = 32766, OnePs = 66, TenPs = 0, HundredPs = 0, unit_float = 0.1234, unit_string = "unit_0" }
[10:01:35.058581067] (+0.009938530) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 5 }, { vpid = 32766 }, { my_Time = "10:01:35", PID = 32766, OnePs = 66, TenPs = 0, HundredPs = 1, unit_float = 1.1234, unit_string = "unit_1" }
[10:01:35.068569067] (+0.009988000) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 5 }, { vpid = 32766 }, { my_Time = "10:01:35", PID = 32766, OnePs = 66, TenPs = 0, HundredPs = 2, unit_float = 2.1234, unit_string = "unit_2" }
[10:01:35.078619025] (+0.010049958) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 5 }, { vpid = 32766 }, { my_Time = "10:01:35", PID = 32766, OnePs = 66, TenPs = 0, HundredPs = 3, unit_float = 3.1234, unit_string = "unit_3" }
[10:01:35.088561904] (+0.009942879) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 5 }, { vpid = 32766 }, { my_Time = "10:01:35", PID = 32766, OnePs = 66, TenPs = 0, HundredPs = 4, unit_float = 4.1234, unit_string = "unit_4" }
[10:01:35.098579453] (+0.010017549) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 5 }, { vpid = 32766 }, { my_Time = "10:01:35", PID = 32766, OnePs = 66, TenPs = 0, HundredPs = 5, unit_float = 5.1234, unit_string = "unit_5" }
[10:01:35.108567996] (+0.009988543) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 5 }, { vpid = 32766 }, { my_Time = "10:01:35", PID = 32766, OnePs = 66, TenPs = 0, HundredPs = 6, unit_float = 6.1234, unit_string = "unit_6" }
[10:01:35.118568323] (+0.010000327) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 5 }, { vpid = 32766 }, { my_Time = "10:01:35", PID = 32766, OnePs = 66, TenPs = 0, HundredPs = 7, unit_float = 7.1234, unit_string = "unit_7" }
[10:01:35.128556864] (+0.009988541) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 5 }, { vpid = 32766 }, { my_Time = "10:01:35", PID = 32766, OnePs = 66, TenPs = 0, HundredPs = 8, unit_float = 8.1234, unit_string = "unit_8" }
[SC-1:Node16 Fri Apr 05 10:02:05/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:02:06/cluster/temp/log] # dir /cluster/dumps
total 0
[SC-1:Node16 Fri Apr 05 10:02:06/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:02:11/cluster/temp/log] # echo "Killing TestApp" >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:02:11/cluster/temp/log] # ps -e |grep -c TestApp
8000
[SC-1:Node16 Fri Apr 05 10:02:12/cluster/temp/log] # pkill TestApp
[SC-1:Node16 Fri Apr 05 10:02:18/cluster/temp/log] # echo "Killing Done ." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:02:18/cluster/temp/log] # ps -e |grep -c TestApp
0
[SC-1:Node16 Fri Apr 05 10:02:18/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:02:23/cluster/temp/log] # pkill sar
[SC-1:Node16 Fri Apr 05 10:02:23/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:02:23/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:00:23 CPU %user %nice %system %iowait %steal %idle
10:00:24 all 0.08 0.00 0.33 0.00 0.00 99.58
Start to launch apps when no session is active.
10:00:25 all 8.03 0.00 9.55 0.34 0.00 82.08
10:00:26 all 10.85 0.00 10.85 0.00 0.00 78.31
10:00:27 all 12.76 0.00 12.07 0.00 0.00 75.17
10:00:28 all 13.08 0.00 14.38 0.00 0.00 72.53
10:00:29 all 14.58 0.00 16.31 0.00 0.00 69.11
10:00:30 all 16.04 0.00 17.44 0.00 0.00 66.52
10:00:31 all 15.42 0.00 20.09 0.00 0.00 64.49
10:00:32 all 17.36 0.00 21.16 0.00 0.00 61.49
10:00:33 all 19.52 0.00 21.23 0.00 0.00 59.25
10:00:34 all 20.99 0.00 24.27 0.00 0.00 54.74
10:00:35 all 21.16 0.00 24.96 0.00 0.00 53.88
10:00:36 all 23.81 0.00 24.81 0.00 0.00 51.37
10:00:37 all 23.27 0.00 28.51 0.00 0.00 48.22
10:00:38 all 23.63 0.00 27.67 0.00 0.00 48.70
10:00:39 all 23.36 0.00 28.28 0.00 0.00 48.36
10:00:40 all 27.09 0.00 29.45 0.00 0.00 43.46
10:00:41 all 27.56 0.00 29.94 0.00 0.00 42.49
10:00:42 all 28.57 0.00 30.52 0.00 0.00 40.91
10:00:43 all 28.84 0.00 31.69 0.00 0.00 39.46
10:00:44 all 26.87 0.00 31.96 0.00 0.00 41.18
10:00:45 all 28.77 0.00 31.08 0.00 0.00 40.14
10:00:46 all 27.72 0.00 35.19 0.00 0.00 37.08
10:00:47 all 29.57 0.00 34.07 0.00 0.00 36.36
10:00:48 all 29.32 0.00 33.84 0.00 0.00 36.85
10:00:49 all 32.71 0.00 37.18 0.00 0.00 30.11
10:00:50 all 33.08 0.00 33.67 0.00 0.00 33.25
End of launching apps when no session is active
10:00:51 all 31.88 0.00 34.62 0.17 0.00 33.33
10:00:52 all 29.37 0.00 39.14 0.00 0.00 31.49
10:00:53 all 29.04 0.00 29.40 0.00 0.00 41.56
10:00:54 all 26.55 0.00 35.63 0.00 0.00 37.82
10:00:55 all 28.36 0.00 32.98 0.00 0.00 38.66
10:00:56 all 29.34 0.00 32.82 0.00 0.00 37.84
10:00:57 all 30.11 0.00 33.18 0.00 0.00 36.70
10:00:58 all 28.33 0.00 34.41 0.00 0.00 37.25
10:00:59 all 28.78 0.00 35.22 0.00 0.00 36.00
10:01:00 all 28.99 0.00 33.18 0.00 0.00 37.83
10:01:01 all 29.37 0.00 31.47 0.00 0.00 39.16
10:01:02 all 29.58 0.00 33.55 0.00 0.00 36.87
10:01:03 all 29.62 0.00 32.21 0.00 0.00 38.18
10:01:04 all 31.90 0.00 31.97 0.00 0.00 36.13
Create the session.
10:01:05 all 31.85 0.00 37.33 0.16 0.00 30.66
10:01:06 all 31.05 0.00 31.74 0.00 0.00 37.21
10:01:07 all 29.85 0.00 31.36 0.00 0.00 38.79
10:01:08 all 30.79 0.00 33.57 0.00 0.00 35.64
10:01:09 all 30.46 0.00 30.46 0.00 0.00 39.07
Enable channel....
10:01:10 all 30.21 0.00 30.62 0.41 0.00 38.77
10:01:11 all 31.82 0.00 37.60 0.00 0.00 30.58
10:01:12 all 30.01 0.00 32.61 0.00 0.00 37.38
10:01:13 all 30.56 0.00 32.60 0.00 0.00 36.85
10:01:14 all 27.81 0.00 38.43 0.00 0.00 33.75
10:01:15 all 28.85 0.00 34.51 0.00 0.00 36.64
10:01:16 all 29.32 0.00 34.55 0.00 0.00 36.13
10:01:17 all 32.56 0.00 35.79 0.00 0.00 31.65
Enable channel done.
Enable channel metadata....
Enable channel metadata done.
10:01:18 all 30.79 0.00 33.78 0.25 0.00 35.19
10:01:19 all 31.39 0.00 31.39 0.00 0.00 37.22
10:01:20 all 32.38 0.00 33.07 0.00 0.00 34.55
10:01:21 all 29.68 0.00 30.10 0.00 0.00 40.22
10:01:22 all 29.96 0.00 29.79 0.00 0.00 40.25
10:01:23 all 29.29 0.00 33.11 0.00 0.00 37.59
Enable Event....
10:01:24 all 32.86 0.00 32.95 0.08 0.00 34.11
Enable Event done.
10:01:25 all 30.13 0.00 32.53 0.17 0.00 37.17
10:01:26 all 29.59 0.00 31.13 0.00 0.00 39.28
10:01:27 all 27.56 0.00 33.05 0.00 0.00 39.39
10:01:28 all 27.47 0.00 31.20 0.00 0.00 41.33
10:01:29 all 29.08 0.00 31.43 0.00 0.00 39.50
Activate the session.
10:01:30 all 32.00 0.00 32.65 0.24 0.00 35.10
10:01:31 all 36.53 0.00 34.52 0.00 0.00 28.95
10:01:32 all 40.68 0.00 35.84 0.00 0.00 23.47
10:01:33 all 46.98 0.00 36.24 0.00 0.00 16.78
10:01:34 all 50.66 0.00 34.15 0.00 0.00 15.19
Activate session Done.
10:01:35 all 51.98 0.00 35.64 0.00 0.00 12.38
10:01:36 all 57.37 0.00 31.44 0.00 0.00 11.19
10:01:37 all 53.92 0.00 31.96 0.00 0.00 14.12
10:01:38 all 54.76 0.00 34.54 0.00 0.00 10.70
10:01:39 all 55.51 0.00 35.91 0.00 0.00 8.58
10:01:40 all 55.86 0.00 28.73 0.00 0.00 15.42
10:01:41 all 52.25 0.00 31.33 0.00 0.00 16.42
10:01:42 all 55.05 0.00 32.45 0.00 0.00 12.50
10:01:43 all 54.39 0.00 30.86 0.00 0.00 14.75
10:01:44 all 54.81 0.00 29.39 0.00 0.00 15.79
10:01:45 all 54.60 0.00 32.64 0.00 0.00 12.76
10:01:46 all 53.13 0.00 32.79 0.00 0.00 14.08
10:01:47 all 55.21 0.00 29.91 0.00 0.00 14.87
Stopping the session...
10:01:48 all 53.40 0.00 33.99 0.16 0.00 12.45
10:01:49 all 53.25 0.00 33.17 0.00 0.00 13.58
10:01:50 all 44.21 0.00 34.24 0.00 0.00 21.54
Stopping done.
10:01:51 all 35.90 0.00 35.90 0.16 0.00 28.03
10:01:52 all 30.21 0.00 30.86 0.40 0.00 38.53
10:01:53 all 29.87 0.00 33.06 0.23 0.00 36.85
10:01:54 all 31.62 0.00 32.18 0.00 0.00 36.20
10:01:55 all 30.23 0.00 32.69 0.00 0.00 37.08
10:01:56 all 31.91 0.00 29.97 0.00 0.00 38.12
10:01:57 all 31.96 0.00 30.53 0.00 0.00 37.51
Destroying the session...
10:01:58 all 31.46 0.00 35.40 0.16 0.00 32.98
10:01:59 all 32.29 0.00 31.96 0.00 0.00 35.75
Destroy done!
10:02:00 all 29.66 0.00 34.37 1.36 0.00 34.61
10:02:01 all 28.27 0.00 33.71 0.00 0.00 38.02
10:02:02 all 30.68 0.00 30.68 0.00 0.00 38.64
10:02:03 all 32.36 0.00 30.86 0.00 0.00 36.78
10:02:04 all 30.46 0.00 32.47 0.00 0.00 37.07
10:02:05 all 28.61 0.00 33.97 0.00 0.00 37.43
10:02:06 all 29.89 0.00 32.47 0.00 0.00 37.63
10:02:07 all 30.14 0.00 35.27 0.00 0.00 34.59
10:02:08 all 30.92 0.00 31.15 0.00 0.00 37.93
10:02:09 all 30.73 0.00 31.86 0.00 0.00 37.41
10:02:10 all 31.49 0.00 32.28 0.00 0.00 36.23
Killing TestApp
10:02:11 all 30.25 0.00 32.08 0.23 0.00 37.44
10:02:12 all 30.07 0.00 36.86 0.00 0.00 33.06
10:02:13 all 26.73 0.00 56.19 0.00 0.00 17.08
10:02:14 all 23.42 0.00 62.01 0.00 0.00 14.57
10:02:15 all 18.83 0.00 61.23 0.00 0.00 19.93
10:02:16 all 15.94 0.00 60.54 0.00 0.00 23.52
10:02:17 all 11.68 0.00 58.04 0.00 0.00 30.28
Killing Done .
10:02:18 all 1.09 0.00 17.09 0.51 0.00 81.31
10:02:19 all 0.00 0.00 0.25 0.00 0.00 99.75
10:02:20 all 0.00 0.00 0.08 0.00 0.00 99.92
10:02:21 all 0.00 0.00 0.17 0.00 0.00 99.83
10:02:22 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:02:23/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:02:23/cluster/temp/log] # rm $TC.load.log
[SC-1:Node16 Fri Apr 05 10:02:23/cluster/temp/log] # babeltrace $TC | grep -c $DOMAIN_EVENT
1655
[SC-1:Node16 Fri Apr 05 10:02:23/cluster/temp/log] # du -h $TC | tail -n 1
1.4M LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run1
[SC-1:Node16 Fri Apr 05 10:02:23/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:02:36/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:02:37/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:02:37/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:02:37/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:02:37/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:02:37/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:02:38/cluster/temp/log] # export TC=LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run2
[SC-1:Node16 Fri Apr 05 10:02:55/cluster/temp/log] # DOMAIN_EVENT="com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec"
[SC-1:Node16 Fri Apr 05 10:02:55/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:02:55/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:02:56/cluster/temp/log] # sar -u 1 300 >> $TC.load.log &
[1] 14803
[SC-1:Node16 Fri Apr 05 10:02:56/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:02:56/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:02:57/cluster/temp/log] # echo "Start to launch apps when no session is active." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:02:57/cluster/temp/log] # #----------------------------------------------------------------------
[SC-1:Node16 Fri Apr 05 10:02:57/cluster/temp/log] # date; time for n in $(seq 1 8000); do (/home/test_apps/TestApp_100psOnly 200 np &); done
Fri Apr 5 10:02:57 EDT 2013

real 0m27.516s
user 0m2.732s
sys 0m1.588s
[SC-1:Node16 Fri Apr 05 10:03:24/cluster/temp/log] # #----------------------------------------------------------------------
[SC-1:Node16 Fri Apr 05 10:03:24/cluster/temp/log] # echo "End of launching apps when no session is active" >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:03:24/cluster/temp/log] # ps -ef |grep -c TestApp
8001
[SC-1:Node16 Fri Apr 05 10:03:25/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:03:26/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:03:26/cluster/temp/log] # #---------------------------- Get PID to trace on --------------------------------------------------
[SC-1:Node16 Fri Apr 05 10:03:26/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:03:27/cluster/temp/log] # sleep 10
[SC-1:Node16 Fri Apr 05 10:03:37/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:03:37/cluster/temp/log] # ps -ef |egrep 'lttng'
root 13798 1 0 Apr03 ? 00:02:24 lttng-sessiond -d
root 14694 4536 0 10:03 pts/1 00:00:00 egrep lttng
root 31628 13798 0 Apr03 ? 00:01:39 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:03:38/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] 14695
[SC-1:Node16 Fri Apr 05 10:03:38/cluster/temp/log] # echo "Create the session." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:03:38/cluster/temp/log] # date; lttng create $TC -U net://192.168.0.1:53000:53001/./
Fri Apr 5 10:03:38 EDT 2013
Session LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run2 created.
Traces will be written in net://192.168.0.1:53000:53001/./
[SC-1:Node16 Fri Apr 05 10:03:38/cluster/temp/log] # lttng list
Available tracing sessions:
1) LTTNGgbf_017_8kAppFirst_NoTimer_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:03:38/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:03:43/cluster/temp/log] # echo "Enable channel...." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:03:43/cluster/temp/log] # date; lttng enable-channel chan1 -u -s $TC --buffers-uid --subbuf-size 16384 #--switch-timer 1000000
Fri Apr 5 10:03:43 EDT 2013
UST channel chan1 enabled for session LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run2
[SC-1:Node16 Fri Apr 05 10:03:51/cluster/temp/log] # echo "Enable channel done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:03:51/cluster/temp/log] # echo "Enable channel metadata...." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:03:51/cluster/temp/log] # date; lttng enable-channel metadata -u -s $TC --buffers-uid --subbuf-size 16384 #--switch-timer 1000000
Fri Apr 5 10:03:51 EDT 2013
UST channel metadata enabled for session LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run2
[SC-1:Node16 Fri Apr 05 10:03:51/cluster/temp/log] # echo "Enable channel metadata done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:03:51/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:03:56/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:03:57/cluster/temp/log] # echo "Enable Event...." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:03:57/cluster/temp/log] # date; lttng enable-event -s $TC -u -c chan1 $DOMAIN_EVENT --filter "PID == $my_pid"
Fri Apr 5 10:03:57 EDT 2013
Filter 'PID == 32764' successfully set
[SC-1:Node16 Fri Apr 05 10:03:58/cluster/temp/log] # echo "Enable Event done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:03:58/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:04:03/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:04:03/cluster/temp/log] # echo "Activate the session." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:04:03/cluster/temp/log] # #---------------------------------------------------- activate session -----------------------
[SC-1:Node16 Fri Apr 05 10:04:03/cluster/temp/log] # date; lttng start;
Fri Apr 5 10:04:03 EDT 2013
Tracing started for session LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run2
[SC-1:Node16 Fri Apr 05 10:04:10/cluster/temp/log] # echo "Activate session Done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:04:10/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:04:11/cluster/temp/log] # lttng list $TC
Tracing session LTTNGgbf_017_8kAppFirst_NoTimer_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: 0
read timer interval: 200000
output: mmap()

Events:
None

- chan1: [enabled]

Attributes:
overwrite mode: 0
subbufers size: 16384
number of subbufers: 4
switch timer interval: 0
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:04:12/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:04:13/cluster/temp/log] # ps -e |grep -c TestApp
8000
[SC-1:Node16 Fri Apr 05 10:04:14/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run2/SC-1/ust/uid/0/64-bit:
total 16
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_9
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_8
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_7
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_5
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_4
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_3
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_2
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_11
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_10
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_1
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_0
-rw-rw---- 1 root root 0 Apr 5 10:03 metadata
-rw-rw---- 1 root root 16384 Apr 5 10:04 chan1_6
[SC-1:Node16 Fri Apr 05 10:04:14/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:04:15/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run2/SC-1/ust/uid/0/64-bit:
total 16
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_9
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_8
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_7
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_5
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_4
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_3
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_2
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_11
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_10
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_1
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_0
-rw-rw---- 1 root root 0 Apr 5 10:03 metadata
-rw-rw---- 1 root root 16384 Apr 5 10:04 chan1_6
[SC-1:Node16 Fri Apr 05 10:04:15/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:04:16/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run2/SC-1/ust/uid/0/64-bit:
total 32
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_9
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_8
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_7
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_4
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_3
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_2
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_11
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_10
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_1
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_0
-rw-rw---- 1 root root 0 Apr 5 10:03 metadata
-rw-rw---- 1 root root 16384 Apr 5 10:04 chan1_6
-rw-rw---- 1 root root 16384 Apr 5 10:04 chan1_5
[SC-1:Node16 Fri Apr 05 10:04:17/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:04:18/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run2/SC-1/ust/uid/0/64-bit:
total 32
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_9
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_8
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_7
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_4
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_3
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_2
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_11
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_10
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_1
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_0
-rw-rw---- 1 root root 0 Apr 5 10:03 metadata
-rw-rw---- 1 root root 16384 Apr 5 10:04 chan1_6
-rw-rw---- 1 root root 16384 Apr 5 10:04 chan1_5
[SC-1:Node16 Fri Apr 05 10:04:18/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:04:19/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run2/SC-1/ust/uid/0/64-bit:
total 32
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_9
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_8
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_7
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_4
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_3
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_2
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_11
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_10
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_1
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_0
-rw-rw---- 1 root root 0 Apr 5 10:03 metadata
-rw-rw---- 1 root root 16384 Apr 5 10:04 chan1_6
-rw-rw---- 1 root root 16384 Apr 5 10:04 chan1_5
[SC-1:Node16 Fri Apr 05 10:04:19/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:04:24/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run2/SC-1/ust/uid/0/64-bit:
total 48
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_9
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_8
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_7
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_4
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_3
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_2
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_10
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_1
-rw-rw---- 1 root root 0 Apr 5 10:03 chan1_0
-rw-rw---- 1 root root 0 Apr 5 10:03 metadata
-rw-rw---- 1 root root 16384 Apr 5 10:04 chan1_6
-rw-rw---- 1 root root 16384 Apr 5 10:04 chan1_5
-rw-rw---- 1 root root 16384 Apr 5 10:04 chan1_11
[SC-1:Node16 Fri Apr 05 10:04:24/cluster/temp/log] # echo "Stopping the session..." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:04:24/cluster/temp/log] # #---------------------------------------------------- De-activate session -----------------------
[SC-1:Node16 Fri Apr 05 10:04:24/cluster/temp/log] # lttng stop
Waiting for data availability
Tracing stopped for session LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run2
[SC-1:Node16 Fri Apr 05 10:04:27/cluster/temp/log] # echo "Stopping done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:04:27/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:04:28/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run2/SC-1/ust/uid/0/64-bit:
total 168
-rw-rw---- 1 root root 4096 Apr 5 10:04 metadata
-rw-rw---- 1 root root 4096 Apr 5 10:04 chan1_9
-rw-rw---- 1 root root 4096 Apr 5 10:04 chan1_8
-rw-rw---- 1 root root 4096 Apr 5 10:04 chan1_7
-rw-rw---- 1 root root 32768 Apr 5 10:04 chan1_6
-rw-rw---- 1 root root 57344 Apr 5 10:04 chan1_5
-rw-rw---- 1 root root 8192 Apr 5 10:04 chan1_4
-rw-rw---- 1 root root 8192 Apr 5 10:04 chan1_3
-rw-rw---- 1 root root 4096 Apr 5 10:04 chan1_2
-rw-rw---- 1 root root 24576 Apr 5 10:04 chan1_11
-rw-rw---- 1 root root 8192 Apr 5 10:04 chan1_10
-rw-rw---- 1 root root 4096 Apr 5 10:04 chan1_1
-rw-rw---- 1 root root 4096 Apr 5 10:04 chan1_0
[SC-1:Node16 Fri Apr 05 10:04:28/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:04:33/cluster/temp/log] # echo "Destroying the session..." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:04:33/cluster/temp/log] # lttng destroy
Session LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run2 destroyed
[SC-1:Node16 Fri Apr 05 10:04:35/cluster/temp/log] # echo "Destroy done! " >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:04:35/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:04:40/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run2/SC-1/ust/uid/0/64-bit:
total 220
-rw-rw---- 1 root root 8192 Apr 5 10:04 metadata
-rw-rw---- 1 root root 8192 Apr 5 10:04 chan1_9
-rw-rw---- 1 root root 8192 Apr 5 10:04 chan1_8
-rw-rw---- 1 root root 8192 Apr 5 10:04 chan1_7
-rw-rw---- 1 root root 36864 Apr 5 10:04 chan1_6
-rw-rw---- 1 root root 61440 Apr 5 10:04 chan1_5
-rw-rw---- 1 root root 12288 Apr 5 10:04 chan1_4
-rw-rw---- 1 root root 12288 Apr 5 10:04 chan1_3
-rw-rw---- 1 root root 8192 Apr 5 10:04 chan1_2
-rw-rw---- 1 root root 28672 Apr 5 10:04 chan1_11
-rw-rw---- 1 root root 12288 Apr 5 10:04 chan1_10
-rw-rw---- 1 root root 8192 Apr 5 10:04 chan1_1
-rw-rw---- 1 root root 8192 Apr 5 10:04 chan1_0
[SC-1:Node16 Fri Apr 05 10:04:40/cluster/temp/log] # pkill relayd
[SC-1:Node16 Fri Apr 05 10:04:41/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:04:41/cluster/temp/log] # babeltrace $TC | head -n 10
[10:04:03.703815816] (+?.?????????) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 0 }, { vpid = 32764 }, { my_Time = "10:04:03", PID = 32764, OnePs = 54, TenPs = 6, HundredPs = 5, unit_float = 5.1234, unit_string = "unit_5" }
[10:04:03.713771028] (+0.009955212) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 6 }, { vpid = 32764 }, { my_Time = "10:04:03", PID = 32764, OnePs = 54, TenPs = 6, HundredPs = 6, unit_float = 6.1234, unit_string = "unit_6" }
[10:04:03.723727337] (+0.009956309) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 6 }, { vpid = 32764 }, { my_Time = "10:04:03", PID = 32764, OnePs = 54, TenPs = 6, HundredPs = 7, unit_float = 7.1234, unit_string = "unit_7" }
[10:04:03.733727224] (+0.009999887) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 6 }, { vpid = 32764 }, { my_Time = "10:04:03", PID = 32764, OnePs = 54, TenPs = 6, HundredPs = 8, unit_float = 8.1234, unit_string = "unit_8" }
[10:04:03.743734467] (+0.010007243) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 6 }, { vpid = 32764 }, { my_Time = "10:04:03", PID = 32764, OnePs = 54, TenPs = 6, HundredPs = 9, unit_float = 9.1234, unit_string = "unit_9" }
[10:04:03.753734525] (+0.010000058) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 6 }, { vpid = 32764 }, { my_Time = "10:04:03", PID = 32764, OnePs = 54, TenPs = 7, HundredPs = 0, unit_float = 0.1234, unit_string = "unit_0" }
[10:04:03.763734258] (+0.009999733) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 6 }, { vpid = 32764 }, { my_Time = "10:04:03", PID = 32764, OnePs = 54, TenPs = 7, HundredPs = 1, unit_float = 1.1234, unit_string = "unit_1" }
[10:04:03.773735132] (+0.010000874) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 6 }, { vpid = 32764 }, { my_Time = "10:04:03", PID = 32764, OnePs = 54, TenPs = 7, HundredPs = 2, unit_float = 2.1234, unit_string = "unit_2" }
[10:04:03.783733667] (+0.009998535) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 6 }, { vpid = 32764 }, { my_Time = "10:04:03", PID = 32764, OnePs = 54, TenPs = 7, HundredPs = 3, unit_float = 3.1234, unit_string = "unit_3" }
[10:04:03.793732816] (+0.009999149) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 6 }, { vpid = 32764 }, { my_Time = "10:04:03", PID = 32764, OnePs = 54, TenPs = 7, HundredPs = 4, unit_float = 4.1234, unit_string = "unit_4" }
[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:04:41/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:04:42/cluster/temp/log] # dir /cluster/dumps
total 0
[SC-1:Node16 Fri Apr 05 10:04:42/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:04:47/cluster/temp/log] # echo "Killing TestApp" >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:04:47/cluster/temp/log] # ps -e |grep -c TestApp
8000
[SC-1:Node16 Fri Apr 05 10:04:48/cluster/temp/log] # pkill TestApp
[SC-1:Node16 Fri Apr 05 10:04:54/cluster/temp/log] # echo "Killing Done ." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:04:54/cluster/temp/log] # ps -e |grep -c TestApp
0
[SC-1:Node16 Fri Apr 05 10:04:55/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:05:00/cluster/temp/log] # pkill sar
[SC-1:Node16 Fri Apr 05 10:05:00/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:05:00/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:02:56 CPU %user %nice %system %iowait %steal %idle
10:02:57 all 0.08 0.00 0.25 0.00 0.00 99.67
Start to launch apps when no session is active.
10:02:58 all 7.55 0.00 10.86 0.51 0.00 81.09
10:02:59 all 9.84 0.00 11.57 0.00 0.00 78.58
10:03:00 all 11.71 0.00 12.50 0.00 0.00 75.79
10:03:01 all 12.40 0.00 13.90 0.00 0.00 73.70
10:03:02 all 13.29 0.00 15.23 0.00 0.00 71.48
10:03:03 all 14.06 0.00 17.62 0.00 0.00 68.33
10:03:04 all 15.23 0.00 17.72 0.00 0.00 67.05
10:03:05 all 16.68 0.00 19.58 0.00 0.00 63.74
10:03:06 all 17.72 0.00 22.02 0.00 0.00 60.26
10:03:07 all 19.28 0.00 21.73 0.00 0.00 58.99
10:03:08 all 20.05 0.00 24.92 0.00 0.00 55.03
10:03:09 all 22.49 0.00 25.95 0.00 0.00 51.56
10:03:10 all 23.62 0.00 25.15 0.00 0.00 51.23
10:03:11 all 23.17 0.00 27.43 0.00 0.00 49.40
10:03:12 all 23.86 0.00 29.11 0.00 0.00 47.03
10:03:13 all 25.71 0.00 29.20 0.00 0.00 45.09
10:03:14 all 25.54 0.00 30.53 0.00 0.00 43.93
10:03:15 all 26.97 0.00 31.87 0.00 0.00 41.16
10:03:16 all 27.07 0.00 32.50 0.00 0.00 40.43
10:03:17 all 28.62 0.00 31.38 0.00 0.00 40.00
10:03:18 all 28.66 0.00 32.27 0.00 0.00 39.07
10:03:19 all 29.33 0.00 33.96 0.00 0.00 36.71
10:03:20 all 29.33 0.00 33.95 0.00 0.00 36.72
10:03:21 all 31.20 0.00 32.41 0.00 0.00 36.40
10:03:22 all 32.87 0.00 33.83 0.00 0.00 33.30
10:03:23 all 29.38 0.00 34.64 0.00 0.00 35.98
10:03:24 all 32.05 0.00 32.86 0.00 0.00 35.09
End of launching apps when no session is active
10:03:25 all 32.97 0.00 33.97 0.27 0.00 32.79
10:03:26 all 27.03 0.00 30.00 0.00 0.00 42.97
10:03:27 all 28.66 0.00 31.69 0.00 0.00 39.65
10:03:28 all 27.72 0.00 35.97 0.00 0.00 36.32
10:03:29 all 28.49 0.00 31.71 0.00 0.00 39.80
10:03:30 all 29.19 0.00 32.06 0.00 0.00 38.76
10:03:31 all 27.44 0.00 35.29 0.00 0.00 37.27
10:03:32 all 30.13 0.00 31.56 0.00 0.00 38.30
10:03:33 all 29.11 0.00 31.22 0.00 0.00 39.67
10:03:34 all 28.38 0.00 34.52 0.00 0.00 37.10
10:03:35 all 28.25 0.00 33.46 0.00 0.00 38.29
10:03:36 all 28.75 0.00 33.49 0.00 0.00 37.76
10:03:37 all 28.68 0.00 35.74 0.00 0.00 35.58
10:03:38 all 31.30 0.00 34.66 0.00 0.00 34.04
Create the session.
10:03:39 all 30.05 0.00 33.65 0.24 0.00 36.06
10:03:40 all 28.86 0.00 34.90 0.00 0.00 36.24
10:03:41 all 30.52 0.00 31.33 0.00 0.00 38.15
10:03:42 all 26.62 0.00 33.74 0.00 0.00 39.64
10:03:43 all 29.04 0.00 31.68 0.00 0.00 39.27
Enable channel....
10:03:44 all 30.76 0.00 33.33 0.33 0.00 35.58
10:03:45 all 30.23 0.00 35.70 0.00 0.00 34.07
10:03:46 all 31.71 0.00 37.28 0.00 0.00 31.00
10:03:47 all 30.95 0.00 38.50 0.00 0.00 30.55
10:03:48 all 32.49 0.00 34.31 0.00 0.00 33.20
10:03:49 all 31.31 0.00 35.62 0.00 0.00 33.07
10:03:50 all 30.09 0.00 38.32 0.00 0.00 31.59
10:03:51 all 31.28 0.00 34.32 0.00 0.00 34.40
Enable channel done.
Enable channel metadata....
Enable channel metadata done.
10:03:52 all 30.38 0.00 32.86 0.25 0.00 36.51
10:03:53 all 30.36 0.00 33.36 0.00 0.00 36.28
10:03:54 all 26.34 0.00 33.50 0.00 0.00 40.16
10:03:55 all 26.64 0.00 32.61 0.00 0.00 40.75
10:03:56 all 32.57 0.00 32.18 0.00 0.00 35.25
10:03:57 all 29.69 0.00 33.12 0.00 0.00 37.19
Enable Event....
10:03:58 all 31.55 0.00 34.87 0.16 0.00 33.41
Enable Event done.
10:03:59 all 30.97 0.00 35.96 0.16 0.00 32.92
10:04:00 all 28.51 0.00 32.80 0.00 0.00 38.68
10:04:01 all 28.34 0.00 31.70 0.00 0.00 39.97
10:04:02 all 28.12 0.00 34.29 0.00 0.00 37.58
10:04:03 all 28.28 0.00 31.01 0.00 0.00 40.71
Activate the session.
10:04:04 all 30.69 0.00 32.74 0.09 0.00 36.49
10:04:05 all 38.09 0.00 35.73 0.00 0.00 26.18
10:04:06 all 42.21 0.00 34.51 0.00 0.00 23.28
10:04:07 all 45.14 0.00 34.13 0.00 0.00 20.73
10:04:08 all 49.76 0.00 33.04 0.00 0.00 17.21
10:04:09 all 52.73 0.00 32.96 0.00 0.00 14.31
10:04:10 all 53.70 0.00 32.38 0.00 0.00 13.92
Activate session Done.
10:04:11 all 55.19 0.00 32.16 0.08 0.00 12.56
10:04:12 all 55.35 0.00 32.10 0.00 0.00 12.55
10:04:13 all 57.06 0.00 29.14 0.00 0.00 13.80
10:04:14 all 56.90 0.00 32.93 0.00 0.00 10.17
10:04:15 all 56.17 0.00 35.47 0.00 0.00 8.36
10:04:16 all 53.54 0.00 31.31 0.00 0.00 15.15
10:04:17 all 54.31 0.00 31.31 0.00 0.00 14.38
10:04:18 all 55.44 0.00 32.75 0.00 0.00 11.80
10:04:19 all 54.18 0.00 31.32 0.00 0.00 14.50
10:04:20 all 53.60 0.00 31.08 0.00 0.00 15.33
10:04:21 all 53.42 0.00 35.75 0.00 0.00 10.83
10:04:22 all 53.76 0.00 31.11 0.00 0.00 15.13
10:04:23 all 54.46 0.00 31.05 0.00 0.00 14.49
Stopping the session...
10:04:24 all 54.79 0.00 33.39 0.18 0.00 11.64
10:04:25 all 53.14 0.00 31.43 0.00 0.00 15.42
10:04:26 all 45.41 0.00 32.85 0.00 0.00 21.74
10:04:27 all 38.04 0.00 35.10 0.00 0.00 26.86
Stopping done.
10:04:28 all 28.66 0.00 30.18 0.17 0.00 41.00
10:04:29 all 29.22 0.00 30.86 0.82 0.00 39.09
10:04:30 all 28.23 0.00 33.81 0.00 0.00 37.95
10:04:31 all 29.14 0.00 30.62 0.00 0.00 40.25
10:04:32 all 26.24 0.00 31.19 0.00 0.00 42.57
10:04:33 all 29.37 0.00 31.56 0.00 0.00 39.07
Destroying the session...
10:04:34 all 30.98 0.00 31.49 0.09 0.00 37.45
10:04:35 all 33.03 0.00 31.68 0.00 0.00 35.29
Destroy done!
10:04:36 all 31.59 0.00 33.39 1.29 0.00 33.73
10:04:37 all 28.05 0.00 29.49 0.00 0.00 42.46
10:04:38 all 27.94 0.00 30.78 0.00 0.00 41.28
10:04:39 all 28.83 0.00 33.25 0.00 0.00 37.92
10:04:40 all 27.32 0.00 33.81 0.00 0.00 38.88
10:04:41 all 28.35 0.00 33.33 0.00 0.00 38.32
10:04:42 all 31.66 0.00 31.82 0.00 0.00 36.52
10:04:43 all 29.50 0.00 31.46 0.00 0.00 39.04
10:04:44 all 27.77 0.00 31.12 0.00 0.00 41.11
10:04:45 all 28.68 0.00 30.57 0.00 0.00 40.75
10:04:46 all 28.56 0.00 30.87 0.00 0.00 40.57
10:04:47 all 28.92 0.00 30.72 0.00 0.00 40.36
Killing TestApp
10:04:48 all 31.99 0.00 34.13 0.16 0.00 33.72
10:04:49 all 26.25 0.00 52.00 0.00 0.00 21.75
10:04:50 all 25.88 0.00 57.60 0.00 0.00 16.53
10:04:51 all 22.58 0.00 57.47 0.00 0.00 19.95
10:04:52 all 20.60 0.00 57.37 0.00 0.00 22.03
10:04:53 all 16.31 0.00 58.91 0.00 0.00 24.78
10:04:54 all 13.99 0.00 57.45 0.00 0.00 28.56
Killing Done .
10:04:55 all 7.03 0.00 41.17 0.50 0.00 51.30
10:04:56 all 0.00 0.00 0.33 0.00 0.00 99.67
10:04:57 all 0.00 0.00 0.00 0.00 0.00 100.00
10:04:58 all 0.00 0.00 0.17 0.00 0.00 99.83
10:04:59 all 0.08 0.00 0.25 0.00 0.00 99.67
[1]+ Terminated sar -u 1 300 >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:05:00/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:05:00/cluster/temp/log] # rm $TC.load.log
[SC-1:Node16 Fri Apr 05 10:05:00/cluster/temp/log] # babeltrace $TC | grep -c $DOMAIN_EVENT
2060
[SC-1:Node16 Fri Apr 05 10:05:00/cluster/temp/log] # du -h $TC | tail -n 1
244K LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run2
[SC-1:Node16 Fri Apr 05 10:05:00/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:37:16/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:37:16/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:37:16/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:37:16/cluster/temp/log] # export TC=LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run3
[SC-1:Node16 Fri Apr 05 10:37:32/cluster/temp/log] # DOMAIN_EVENT="com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec"
[SC-1:Node16 Fri Apr 05 10:37:32/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:37:32/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:37:33/cluster/temp/log] # sar -u 1 300 >> $TC.load.log &
[1] 2960
[SC-1:Node16 Fri Apr 05 10:37:33/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:37:33/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:37:34/cluster/temp/log] # echo "Start to launch apps when no session is active." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:37:34/cluster/temp/log] # #----------------------------------------------------------------------
[SC-1:Node16 Fri Apr 05 10:37:34/cluster/temp/log] # date; time for n in $(seq 1 8000); do (/home/test_apps/TestApp_100psOnly 200 np &); done
Fri Apr 5 10:37:34 EDT 2013

real 0m28.264s
user 0m2.992s
sys 0m1.712s
[SC-1:Node16 Fri Apr 05 10:38:02/cluster/temp/log] # #----------------------------------------------------------------------
[SC-1:Node16 Fri Apr 05 10:38:02/cluster/temp/log] # echo "End of launching apps when no session is active" >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:38:02/cluster/temp/log] # ps -ef |grep -c TestApp
8001
[SC-1:Node16 Fri Apr 05 10:38:03/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:38:04/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:38:04/cluster/temp/log] # #---------------------------- Get PID to trace on --------------------------------------------------
[SC-1:Node16 Fri Apr 05 10:38:04/cluster/temp/log] # export my_pid=$(ps -e |grep TestApp | tail -n 1 | awk {'print $1'}); echo $my_pid
32767
[SC-1:Node16 Fri Apr 05 10:38:05/cluster/temp/log] # sleep 10
[SC-1:Node16 Fri Apr 05 10:38:15/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:38:15/cluster/temp/log] # ps -ef |egrep 'lttng'
root 2757 4536 0 10:38 pts/1 00:00:00 egrep lttng
root 13798 1 0 Apr03 ? 00:02:31 lttng-sessiond -d
root 31628 13798 0 Apr03 ? 00:01:40 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:38:16/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] 2758
[SC-1:Node16 Fri Apr 05 10:38:16/cluster/temp/log] # echo "Create the session." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:38:16/cluster/temp/log] # date; lttng create $TC -U net://192.168.0.1:53000:53001/./
Fri Apr 5 10:38:16 EDT 2013
Session LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run3 created.
Traces will be written in net://192.168.0.1:53000:53001/./
[SC-1:Node16 Fri Apr 05 10:38:16/cluster/temp/log] # lttng list
Available tracing sessions:
1) LTTNGgbf_017_8kAppFirst_NoTimer_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:38:16/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:38:21/cluster/temp/log] # echo "Enable channel...." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:38:21/cluster/temp/log] # date; lttng enable-channel chan1 -u -s $TC --buffers-uid --subbuf-size 16384 #--switch-timer 1000000
Fri Apr 5 10:38:21 EDT 2013
UST channel chan1 enabled for session LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run3
[SC-1:Node16 Fri Apr 05 10:38:28/cluster/temp/log] # echo "Enable channel done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:38:28/cluster/temp/log] # echo "Enable channel metadata...." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:38:28/cluster/temp/log] # date; lttng enable-channel metadata -u -s $TC --buffers-uid --subbuf-size 16384 #--switch-timer 1000000
Fri Apr 5 10:38:28 EDT 2013
UST channel metadata enabled for session LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run3
[SC-1:Node16 Fri Apr 05 10:38:28/cluster/temp/log] # echo "Enable channel metadata done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:38:28/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:38:33/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:38:34/cluster/temp/log] # echo "Enable Event...." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:38:34/cluster/temp/log] # date; lttng enable-event -s $TC -u -c chan1 $DOMAIN_EVENT --filter "PID == $my_pid"
Fri Apr 5 10:38:34 EDT 2013
Filter 'PID == 32767' successfully set
[SC-1:Node16 Fri Apr 05 10:38:35/cluster/temp/log] # echo "Enable Event done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:38:35/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:38:40/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:38:40/cluster/temp/log] # echo "Activate the session." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:38:40/cluster/temp/log] # #---------------------------------------------------- activate session -----------------------
[SC-1:Node16 Fri Apr 05 10:38:40/cluster/temp/log] # date; lttng start;
Fri Apr 5 10:38:40 EDT 2013
Tracing started for session LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run3
[SC-1:Node16 Fri Apr 05 10:38:46/cluster/temp/log] # echo "Activate session Done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:38:46/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:38:47/cluster/temp/log] # lttng list $TC
Tracing session LTTNGgbf_017_8kAppFirst_NoTimer_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: 0
read timer interval: 200000
output: mmap()

Events:
None

- chan1: [enabled]

Attributes:
overwrite mode: 0
subbufers size: 16384
number of subbufers: 4
switch timer interval: 0
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:38:47/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:38:48/cluster/temp/log] # ps -e |grep -c TestApp
8000
[SC-1:Node16 Fri Apr 05 10:38:50/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run3/SC-1/ust/uid/0/64-bit:
total 0
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_9
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_8
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_7
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_6
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_5
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_4
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_3
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_2
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_11
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_10
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_1
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_0
-rw-rw---- 1 root root 0 Apr 5 10:38 metadata
[SC-1:Node16 Fri Apr 05 10:38:50/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:38:51/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run3/SC-1/ust/uid/0/64-bit:
total 0
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_9
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_8
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_7
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_6
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_5
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_4
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_3
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_2
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_11
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_10
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_1
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_0
-rw-rw---- 1 root root 0 Apr 5 10:38 metadata
[SC-1:Node16 Fri Apr 05 10:38:51/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:38:52/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run3/SC-1/ust/uid/0/64-bit:
total 0
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_9
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_8
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_7
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_6
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_5
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_4
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_3
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_2
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_11
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_10
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_1
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_0
-rw-rw---- 1 root root 0 Apr 5 10:38 metadata
[SC-1:Node16 Fri Apr 05 10:38:52/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:38:53/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run3/SC-1/ust/uid/0/64-bit:
total 0
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_9
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_8
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_7
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_6
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_5
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_4
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_3
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_2
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_11
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_10
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_1
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_0
-rw-rw---- 1 root root 0 Apr 5 10:38 metadata
[SC-1:Node16 Fri Apr 05 10:38:53/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:38:54/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run3/SC-1/ust/uid/0/64-bit:
total 0
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_9
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_8
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_7
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_6
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_5
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_4
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_3
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_2
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_11
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_10
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_1
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_0
-rw-rw---- 1 root root 0 Apr 5 10:38 metadata
[SC-1:Node16 Fri Apr 05 10:38:54/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:38:59/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run3/SC-1/ust/uid/0/64-bit:
total 16
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_9
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_8
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_7
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_6
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_5
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_4
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_3
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_2
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_11
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_10
-rw-rw---- 1 root root 0 Apr 5 10:38 chan1_1
-rw-rw---- 1 root root 0 Apr 5 10:38 metadata
-rw-rw---- 1 root root 16384 Apr 5 10:38 chan1_0
[SC-1:Node16 Fri Apr 05 10:38:59/cluster/temp/log] # echo "Stopping the session..." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:38:59/cluster/temp/log] # #---------------------------------------------------- De-activate session -----------------------
[SC-1:Node16 Fri Apr 05 10:38:59/cluster/temp/log] # lttng stop
Waiting for data availability
Tracing stopped for session LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run3
[SC-1:Node16 Fri Apr 05 10:39:02/cluster/temp/log] # echo "Stopping done." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:39:02/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:39:03/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run3/SC-1/ust/uid/0/64-bit:
total 708
-rw-rw---- 1 root root 4096 Apr 5 10:39 metadata
-rw-rw---- 1 root root 12288 Apr 5 10:39 chan1_9
-rw-rw---- 1 root root 8192 Apr 5 10:39 chan1_8
-rw-rw---- 1 root root 225280 Apr 5 10:39 chan1_7
-rw-rw---- 1 root root 376832 Apr 5 10:39 chan1_6
-rw-rw---- 1 root root 12288 Apr 5 10:39 chan1_5
-rw-rw---- 1 root root 4096 Apr 5 10:39 chan1_4
-rw-rw---- 1 root root 16384 Apr 5 10:39 chan1_3
-rw-rw---- 1 root root 16384 Apr 5 10:39 chan1_2
-rw-rw---- 1 root root 4096 Apr 5 10:39 chan1_11
-rw-rw---- 1 root root 4096 Apr 5 10:39 chan1_10
-rw-rw---- 1 root root 12288 Apr 5 10:39 chan1_1
-rw-rw---- 1 root root 20480 Apr 5 10:39 chan1_0
[SC-1:Node16 Fri Apr 05 10:39:03/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:39:08/cluster/temp/log] # echo "Destroying the session..." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:39:09/cluster/temp/log] # lttng destroy
Session LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run3 destroyed
[SC-1:Node16 Fri Apr 05 10:39:11/cluster/temp/log] # echo "Destroy done! " >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:39:11/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:39:16/cluster/temp/log] # dir -R $TC/SC-1/ust/uid/0/64-bit
LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run3/SC-1/ust/uid/0/64-bit:
total 760
-rw-rw---- 1 root root 8192 Apr 5 10:39 metadata
-rw-rw---- 1 root root 16384 Apr 5 10:39 chan1_9
-rw-rw---- 1 root root 12288 Apr 5 10:39 chan1_8
-rw-rw---- 1 root root 229376 Apr 5 10:39 chan1_7
-rw-rw---- 1 root root 380928 Apr 5 10:39 chan1_6
-rw-rw---- 1 root root 16384 Apr 5 10:39 chan1_5
-rw-rw---- 1 root root 8192 Apr 5 10:39 chan1_4
-rw-rw---- 1 root root 20480 Apr 5 10:39 chan1_3
-rw-rw---- 1 root root 20480 Apr 5 10:39 chan1_2
-rw-rw---- 1 root root 8192 Apr 5 10:39 chan1_11
-rw-rw---- 1 root root 8192 Apr 5 10:39 chan1_10
-rw-rw---- 1 root root 16384 Apr 5 10:39 chan1_1
-rw-rw---- 1 root root 24576 Apr 5 10:39 chan1_0
[SC-1:Node16 Fri Apr 05 10:39:16/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:39:17/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:39:17/cluster/temp/log] # babeltrace $TC | head -n 10
[10:38:41.750269257] (+?.?????????) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 4 }, { vpid = 32767 }, { my_Time = "10:38:41", PID = 32767, OnePs = 43, TenPs = 7, HundredPs = 0, unit_float = 0.1234, unit_string = "unit_0" }
[10:38:41.760253276] (+0.009984019) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 4 }, { vpid = 32767 }, { my_Time = "10:38:41", PID = 32767, OnePs = 43, TenPs = 7, HundredPs = 1, unit_float = 1.1234, unit_string = "unit_1" }
[10:38:41.770217811] (+0.009964535) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 10 }, { vpid = 32767 }, { my_Time = "10:38:41", PID = 32767, OnePs = 43, TenPs = 7, HundredPs = 2, unit_float = 2.1234, unit_string = "unit_2" }
[10:38:41.780220698] (+0.010002887) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 10 }, { vpid = 32767 }, { my_Time = "10:38:41", PID = 32767, OnePs = 43, TenPs = 7, HundredPs = 3, unit_float = 3.1234, unit_string = "unit_3" }
[10:38:41.790221086] (+0.010000388) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 10 }, { vpid = 32767 }, { my_Time = "10:38:41", PID = 32767, OnePs = 43, TenPs = 7, HundredPs = 4, unit_float = 4.1234, unit_string = "unit_4" }
[10:38:41.800220968] (+0.009999882) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 10 }, { vpid = 32767 }, { my_Time = "10:38:41", PID = 32767, OnePs = 43, TenPs = 7, HundredPs = 5, unit_float = 5.1234, unit_string = "unit_5" }
[10:38:41.810220056] (+0.009999088) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 10 }, { vpid = 32767 }, { my_Time = "10:38:41", PID = 32767, OnePs = 43, TenPs = 7, HundredPs = 6, unit_float = 6.1234, unit_string = "unit_6" }
[10:38:41.820221613] (+0.010001557) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 10 }, { vpid = 32767 }, { my_Time = "10:38:41", PID = 32767, OnePs = 43, TenPs = 7, HundredPs = 7, unit_float = 7.1234, unit_string = "unit_7" }
[10:38:41.830214285] (+0.009992672) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 10 }, { vpid = 32767 }, { my_Time = "10:38:41", PID = 32767, OnePs = 43, TenPs = 7, HundredPs = 8, unit_float = 8.1234, unit_string = "unit_8" }
[10:38:41.840213673] (+0.009999388) SC-1 com_ericsson_cba_trace_testapp100_hightraf:HundredPerSec: { cpu_id = 10 }, { vpid = 32767 }, { my_Time = "10:38:41", PID = 32767, OnePs = 43, TenPs = 7, HundredPs = 9, unit_float = 9.1234, unit_string = "unit_9" }
[SC-1:Node16 Fri Apr 05 10:39:17/cluster/temp/log] # sleep 1
[SC-1:Node16 Fri Apr 05 10:39:18/cluster/temp/log] # dir /cluster/dumps
total 0
[SC-1:Node16 Fri Apr 05 10:39:18/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:39:23/cluster/temp/log] # echo "Killing TestApp" >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:39:23/cluster/temp/log] # ps -e |grep -c TestApp
8000
[SC-1:Node16 Fri Apr 05 10:39:24/cluster/temp/log] # pkill TestApp
[SC-1:Node16 Fri Apr 05 10:39:28/cluster/temp/log] # echo "Killing Done ." >> $TC.load.log
[SC-1:Node16 Fri Apr 05 10:39:28/cluster/temp/log] # ps -e |grep -c TestApp
0
[SC-1:Node16 Fri Apr 05 10:39:28/cluster/temp/log] # sleep 5
[SC-1:Node16 Fri Apr 05 10:39:33/cluster/temp/log] # pkill sar
[SC-1:Node16 Fri Apr 05 10:39:33/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:39:33/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:37:33 CPU %user %nice %system %iowait %steal %idle
10:37:34 all 0.00 0.00 0.42 0.00 0.00 99.58
Start to launch apps when no session is active.
10:37:35 all 8.04 0.00 9.65 0.17 0.00 82.13
10:37:36 all 9.44 0.00 11.60 0.00 0.00 78.96
10:37:37 all 11.56 0.00 12.26 0.00 0.00 76.18
10:37:38 all 12.12 0.00 13.27 0.00 0.00 74.60
10:37:39 all 13.82 0.00 14.88 0.00 0.00 71.30
10:37:40 all 14.02 0.00 18.08 0.00 0.00 67.90
10:37:41 all 17.19 0.00 16.67 0.00 0.00 66.14
10:37:42 all 17.93 0.00 18.97 0.00 0.00 63.10
10:37:43 all 19.18 0.00 21.23 0.00 0.00 59.59
10:37:44 all 20.32 0.00 23.14 0.00 0.00 56.53
10:37:45 all 21.69 0.00 23.29 0.00 0.00 55.02
10:37:46 all 22.40 0.00 25.12 0.00 0.00 52.48
10:37:47 all 23.49 0.00 28.21 0.00 0.00 48.30
10:37:48 all 24.67 0.00 26.09 0.00 0.00 49.25
10:37:49 all 25.54 0.00 27.51 0.00 0.00 46.95
10:37:50 all 26.88 0.00 31.19 0.00 0.00 41.93
10:37:51 all 27.36 0.00 29.17 0.00 0.00 43.47
10:37:52 all 26.73 0.00 30.24 0.00 0.00 43.02
10:37:53 all 27.88 0.00 33.76 0.00 0.00 38.36
10:37:54 all 27.08 0.00 31.96 0.00 0.00 40.96
10:37:55 all 27.53 0.00 30.86 0.00 0.00 41.61
10:37:56 all 29.08 0.00 33.48 0.00 0.00 37.45
10:37:57 all 29.46 0.00 32.30 0.00 0.00 38.24
10:37:58 all 28.87 0.00 34.12 0.00 0.00 37.00
10:37:59 all 30.73 0.00 37.82 0.00 0.00 31.45
10:38:00 all 30.18 0.00 34.65 0.00 0.00 35.17
10:38:01 all 30.48 0.00 34.45 0.00 0.00 35.07
10:38:02 all 32.91 0.00 36.46 0.00 0.00 30.63
End of launching apps when no session is active
10:38:03 all 29.14 0.00 35.65 0.26 0.00 34.95
10:38:04 all 30.20 0.00 32.73 0.00 0.00 37.07
10:38:05 all 30.33 0.00 35.43 0.00 0.00 34.24
10:38:06 all 28.32 0.00 31.54 0.00 0.00 40.14
10:38:07 all 29.07 0.00 30.74 0.08 0.00 40.10
10:38:08 all 30.48 0.00 32.91 0.00 0.00 36.61
10:38:09 all 29.66 0.00 32.45 0.00 0.00 37.89
10:38:10 all 28.77 0.00 32.57 0.00 0.00 38.66
10:38:11 all 32.35 0.00 29.72 0.00 0.00 37.93
10:38:12 all 27.58 0.00 35.07 0.00 0.00 37.35
10:38:13 all 30.52 0.00 30.03 0.00 0.00 39.45
10:38:14 all 27.99 0.00 33.33 0.00 0.00 38.68
10:38:15 all 29.20 0.00 34.19 0.00 0.00 36.60
10:38:16 all 30.02 0.00 34.99 0.00 0.00 34.99
Create the session.
10:38:17 all 31.77 0.00 31.61 0.23 0.00 36.38
10:38:18 all 31.22 0.00 32.88 0.00 0.00 35.90
10:38:19 all 29.03 0.00 34.24 0.00 0.00 36.73
10:38:20 all 30.12 0.00 33.36 0.00 0.00 36.52
10:38:21 all 31.62 0.00 32.26 0.00 0.00 36.12
Enable channel....
10:38:22 all 30.02 0.00 34.99 0.32 0.00 34.67
10:38:23 all 31.73 0.00 33.10 0.00 0.00 35.17
10:38:24 all 30.26 0.00 37.59 0.00 0.00 32.16
10:38:25 all 32.83 0.00 32.33 0.00 0.00 34.83
10:38:26 all 32.66 0.00 33.87 0.00 0.00 33.47
10:38:27 all 32.39 0.00 38.12 0.00 0.00 29.49
10:38:28 all 32.43 0.00 33.50 0.00 0.00 34.07
Enable channel done.
Enable channel metadata....
Enable channel metadata done.
10:38:29 all 30.55 0.00 31.98 0.25 0.00 37.22
10:38:30 all 28.69 0.00 33.91 0.00 0.00 37.40
10:38:31 all 28.72 0.00 30.93 0.00 0.00 40.34
10:38:32 all 28.66 0.00 32.54 0.00 0.00 38.80
10:38:33 all 28.72 0.00 34.63 0.00 0.00 36.65
10:38:34 all 28.93 0.00 32.38 0.00 0.00 38.69
Enable Event....
10:38:35 all 33.06 0.00 31.56 0.17 0.00 35.22
Enable Event done.
10:38:36 all 30.77 0.00 34.34 0.16 0.00 34.73
10:38:37 all 29.69 0.00 32.42 0.08 0.00 37.81
10:38:38 all 30.94 0.00 30.94 0.00 0.00 38.13
10:38:39 all 32.62 0.00 30.26 0.00 0.00 37.12
10:38:40 all 30.75 0.00 29.93 0.00 0.00 39.32
Activate the session.
10:38:41 all 34.04 0.00 32.47 0.16 0.00 33.33
10:38:42 all 39.21 0.00 34.16 0.00 0.00 26.62
10:38:43 all 45.36 0.00 34.66 0.00 0.00 19.98
10:38:44 all 46.73 0.00 33.88 0.00 0.00 19.39
10:38:45 all 50.42 0.00 33.28 0.00 0.00 16.31
10:38:46 all 54.67 0.00 35.65 0.00 0.00 9.68
Activate session Done.
10:38:47 all 54.75 0.00 32.25 0.08 0.00 12.92
10:38:48 all 54.74 0.00 30.58 0.00 0.00 14.68
10:38:49 all 56.77 0.00 33.82 0.00 0.00 9.41
10:38:50 all 55.30 0.00 35.18 0.00 0.00 9.52
10:38:51 all 55.98 0.00 30.04 0.00 0.00 13.97
10:38:52 all 53.65 0.00 35.77 0.00 0.00 10.58
10:38:53 all 52.92 0.00 31.99 0.00 0.00 15.09
10:38:54 all 55.49 0.00 29.64 0.00 0.00 14.86
10:38:55 all 53.47 0.00 34.62 0.00 0.00 11.91
10:38:56 all 54.13 0.00 29.77 0.00 0.00 16.10
10:38:57 all 54.24 0.00 30.73 0.00 0.00 15.03
10:38:58 all 54.13 0.00 31.90 0.00 0.00 13.97
10:38:59 all 52.56 0.00 34.26 0.00 0.00 13.18
Stopping the session...
10:39:00 all 52.90 0.00 32.20 0.17 0.00 14.74
10:39:01 all 51.96 0.00 33.36 0.00 0.00 14.68
10:39:02 all 44.10 0.00 35.15 0.00 0.00 20.75
Stopping done.
10:39:03 all 31.75 0.00 32.44 0.17 0.00 35.64
10:39:04 all 30.47 0.00 30.12 0.70 0.00 38.70
10:39:05 all 27.78 0.00 29.42 0.00 0.00 42.80
10:39:06 all 28.62 0.00 30.35 0.00 0.00 41.04
10:39:07 all 29.97 0.00 31.86 0.00 0.00 38.18
10:39:08 all 28.39 0.00 30.56 0.00 0.00 41.05
Destroying the session...
10:39:09 all 28.83 0.00 30.41 0.17 0.00 40.60
10:39:10 all 33.45 0.00 31.40 0.00 0.00 35.15
10:39:11 all 32.75 0.00 33.95 0.00 0.00 33.31
Destroy done!
10:39:12 all 30.46 0.00 30.29 1.27 0.00 37.99
10:39:13 all 25.86 0.00 31.60 0.00 0.00 42.54
10:39:14 all 27.10 0.00 30.44 0.00 0.00 42.46
10:39:15 all 26.03 0.00 30.92 0.00 0.00 43.06
10:39:16 all 28.36 0.00 29.73 0.00 0.00 41.90
10:39:17 all 31.86 0.00 31.51 0.00 0.00 36.63
10:39:18 all 27.47 0.00 30.70 0.00 0.00 41.84
10:39:19 all 28.68 0.00 30.26 0.00 0.00 41.06
10:39:20 all 28.68 0.00 31.32 0.00 0.00 40.00
10:39:21 all 26.01 0.00 32.38 0.00 0.00 41.61
10:39:22 all 26.60 0.00 30.68 0.00 0.00 42.72
Killing TestApp
10:39:23 all 28.24 0.00 31.69 0.18 0.00 39.89
10:39:24 all 31.39 0.00 35.20 0.00 0.00 33.41
10:39:25 all 23.31 0.00 59.37 0.00 0.00 17.32
10:39:26 all 22.78 0.00 64.03 0.00 0.00 13.19
10:39:27 all 20.77 0.00 60.56 0.00 0.00 18.67
10:39:28 all 17.16 0.00 55.34 0.00 0.00 27.50
Killing Done .
10:39:29 all 7.88 0.00 48.45 0.34 0.00 43.34
10:39:30 all 0.08 0.00 0.42 0.00 0.00 99.50
10:39:31 all 0.00 0.00 0.08 0.00 0.00 99.92
10:39:32 all 0.00 0.00 0.08 0.00 0.00 99.92
10:39:33 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:39:33/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:39:33/cluster/temp/log] # rm $TC.load.log
[SC-1:Node16 Fri Apr 05 10:39:33/cluster/temp/log] # babeltrace $TC | grep -c $DOMAIN_EVENT
1943
[SC-1:Node16 Fri Apr 05 10:39:34/cluster/temp/log] # du -h $TC | tail -n 1
784K LTTNGgbf_017_8kAppFirst_NoTimer_Pid_buf16k_100ps_run3
[SC-1:Node16 Fri Apr 05 10:39:34/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:39:55/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:39:55/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:39:55/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:39:56/cluster/temp/log] #
[SC-1:Node16 Fri Apr 05 10:39:56/cluster/temp/log] #
(1-1/9)