Project

General

Profile

Bug #539 » patch539_jun10_terminal.log

terminal log showing ps printout when the TC is executed - Tan le tran, 06/10/2013 11:44 AM

 
[SC-1:Node16 Mon Jun 10 11:18:36/cluster/temp/tdlt/SDP/EA_jun09am] # cmw-sdp-import *.sdp
ERIC-TRACE_EA_Common-CXP9040232_1-R3A01 imported (type=Bundle)
ERIC-TRACE_EA_Install-CXP9021071_1-R3A01 imported (type=Campaign)
ERIC-TRACE_EA_Remove-CXP9021071_1-R3A01 imported (type=Campaign)
ERIC-TRACE_EA_SC-CXP9040241_1-R3A01 imported (type=Bundle)
ERIC-TRACE_EA_Upgrade-CXP9021071_1-R3A01 imported (type=Campaign)
[SC-1:Node16 Mon Jun 10 11:18:44/cluster/temp/tdlt/SDP/EA_jun09am] # cmw-campaign-start --disable-backup ERIC-TRACE_EA_Install-CXP9021071_1-R3A01
[SC-1:Node16 Mon Jun 10 11:18:59/cluster/temp/tdlt/SDP/EA_jun09am] # cmw-campaign-status ERIC-TRACE_EA_Install-CXP9021071_1-R3A01
ERIC-TRACE_EA_Install-CXP9021071_1-R3A01=EXECUTING
[SC-1:Node16 Mon Jun 10 11:19:04/cluster/temp/tdlt/SDP/EA_jun09am] # cmw-campaign-status ERIC-TRACE_EA_Install-CXP9021071_1-R3A01
ERIC-TRACE_EA_Install-CXP9021071_1-R3A01=COMPLETED
[SC-1:Node16 Mon Jun 10 11:22:37/cluster/temp/tdlt/SDP/EA_jun09am] # cmw-campaign-commit ERIC-TRACE_EA_Install-CXP9021071_1-R3A01
[SC-1:Node16 Mon Jun 10 11:22:50/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:22:51/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:22:51/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:22:51/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:22:51/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:22:52/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:22:52/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:22:52/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:22:52/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:22:52/cluster/temp/tdlt/SDP/EA_jun09am] # dir
total 8376
-rw-r--r-- 1 root root 343 Jun 10 06:57 README
-rwxr-xr-x 1 root root 3820314 Jun 10 07:09 LttngTest
-rwxr-xr-x 1 root root 192442 Jun 10 09:06 TestApp_type1
-rwxr-xr-x 1 root root 85965 Jun 10 09:06 TestApp_Thread100
-rwxr-xr-x 1 root root 237571 Jun 10 09:06 TestApp_Thread1
-rwxr-xr-x 1 root root 69529 Jun 10 09:06 TestApp_Mini1
-rwxr-xr-x 1 root root 104342 Jun 10 09:06 TestApp_Limit1
-rwxr-xr-x 1 root root 103502 Jun 10 09:06 TestApp_IwillCrash
-rwxr-xr-x 1 root root 78239 Jun 10 09:06 TestApp_Fork100
-rwxr-xr-x 1 root root 221628 Jun 10 09:06 TestApp_Fork1
-rwxr-xr-x 1 root root 161017 Jun 10 09:06 TestApp_100perSecOnly
-rwxr-xr-x 1 root root 193907 Jun 10 09:06 TestApp_Demo
-rw-r--r-- 1 root root 1299 Jun 10 11:11 ERIC-TRACE_EA_Upgrade-CXP9021071_1-R3A01.sdp
-rw-r--r-- 1 root root 144285 Jun 10 11:11 ERIC-TRACE_EA_SC-CXP9040241_1-R3A01.sdp
-rw-r--r-- 1 root root 1321 Jun 10 11:11 ERIC-TRACE_EA_Remove-CXP9021071_1-R3A01.sdp
-rw-r--r-- 1 root root 3041 Jun 10 11:11 ERIC-TRACE_EA_Install-CXP9021071_1-R3A01.sdp
-rw-r--r-- 1 root root 516410 Jun 10 11:11 ERIC-TRACE_EA_Common-CXP9040232_1-R3A01.sdp
-rw-r--r-- 1 root root 195490 Jun 10 11:11 ERIC-TRACE_EA_SC-CXP9040241_1-debuginfo-1-R3A01.x86_64.rpm
-rw-r--r-- 1 root root 2341691 Jun 10 11:11 ERIC-TRACE_EA_Common-CXP9040232_1-debuginfo-1-R3A01.x86_64.rpm
[SC-1:Node16 Mon Jun 10 11:22:53/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:22:54/cluster/temp/tdlt/SDP/EA_jun09am] # dir
total 8376
-rw-r--r-- 1 root root 343 Jun 10 06:57 README
-rwxr-xr-x 1 root root 192442 Jun 10 09:06 TestApp_type1
-rwxr-xr-x 1 root root 85965 Jun 10 09:06 TestApp_Thread100
-rwxr-xr-x 1 root root 237571 Jun 10 09:06 TestApp_Thread1
-rwxr-xr-x 1 root root 69529 Jun 10 09:06 TestApp_Mini1
-rwxr-xr-x 1 root root 104342 Jun 10 09:06 TestApp_Limit1
-rwxr-xr-x 1 root root 103502 Jun 10 09:06 TestApp_IwillCrash
-rwxr-xr-x 1 root root 78239 Jun 10 09:06 TestApp_Fork100
-rwxr-xr-x 1 root root 221628 Jun 10 09:06 TestApp_Fork1
-rwxr-xr-x 1 root root 161017 Jun 10 09:06 TestApp_100perSecOnly
-rwxr-xr-x 1 root root 193907 Jun 10 09:06 TestApp_Demo
-rw-r--r-- 1 root root 1299 Jun 10 11:11 ERIC-TRACE_EA_Upgrade-CXP9021071_1-R3A01.sdp
-rw-r--r-- 1 root root 144285 Jun 10 11:11 ERIC-TRACE_EA_SC-CXP9040241_1-R3A01.sdp
-rw-r--r-- 1 root root 1321 Jun 10 11:11 ERIC-TRACE_EA_Remove-CXP9021071_1-R3A01.sdp
-rw-r--r-- 1 root root 3041 Jun 10 11:11 ERIC-TRACE_EA_Install-CXP9021071_1-R3A01.sdp
-rw-r--r-- 1 root root 516410 Jun 10 11:11 ERIC-TRACE_EA_Common-CXP9040232_1-R3A01.sdp
-rw-r--r-- 1 root root 195490 Jun 10 11:11 ERIC-TRACE_EA_SC-CXP9040241_1-debuginfo-1-R3A01.x86_64.rpm
-rw-r--r-- 1 root root 2341691 Jun 10 11:11 ERIC-TRACE_EA_Common-CXP9040232_1-debuginfo-1-R3A01.x86_64.rpm
-rwxr-xr-x 1 root root 3820314 Jun 10 11:23 LttngTest
[SC-1:Node16 Mon Jun 10 11:23:39/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:23:40/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:23:53/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:23:53/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:23:53/cluster/temp/tdlt/SDP/EA_jun09am] # ps auxwwwf | head -n 1; ps auxwwwf|grep lttng
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 12802 0.0 0.0 4252 568 pts/1 S+ 11:24 0:00 | \_ grep lttng
root 12386 0.0 0.0 85296 908 ? Ssl 11:21 0:00 lttng-sessiond -d
[SC-1:Node16 Mon Jun 10 11:24:08/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:24:09/cluster/temp/tdlt/SDP/EA_jun09am] # ./LttngTest --gtest_filter='*Global*021*'
Lttng test says hello!
Note: Google Test filter = *Global*021*
[==========] Running 1 test from 1 test case.
[----------] Global test environment set-up.
[----------] 1 test from LttngGlobalBufferTest
[ RUN ] LttngGlobalBufferTest.LTTNGgbf_021load_1000ps_App100ps_HundredPerSec_ShortLifeSpan_multipleInactiveSession
Processor load before launching apps(average value of 3 sec, with around 0 apps)
11:24:30 CPU %user %nice %system %iowait %steal %idle
11:24:33 all 0.00 0.00 0.03 0.00 0.00 99.97

Processor load after launching apps(average value of 10 sec, with around 1027 apps)
11:24:38 CPU %user %nice %system %iowait %steal %idle
11:24:48 all 7.62 0.00 14.28 0.01 0.00 78.09

Processor load after session-1 created (still inactive)(average value of 10 sec, with around 1202 apps)
11:24:49 CPU %user %nice %system %iowait %steal %idle
11:24:59 all 8.85 0.00 16.22 0.00 0.00 74.93

Processor load after session dummy1 created (still inactive)(average value of 10 sec, with around 1288 apps)
11:25:01 CPU %user %nice %system %iowait %steal %idle
11:25:11 all 9.73 0.00 17.30 0.00 0.00 72.97

Processor load after session dummy2 created (still inactive)(average value of 10 sec, with around 1202 apps)
11:25:13 CPU %user %nice %system %iowait %steal %idle
11:25:23 all 10.27 0.00 18.91 0.03 0.00 70.79

Processor load after session dummy3 created (still inactive)(average value of 10 sec, with around 1426 apps)
11:25:25 CPU %user %nice %system %iowait %steal %idle
11:25:35 all 11.39 0.00 20.45 0.00 0.00 68.17

Processor load after activating the session(average value of 10 sec, with around 1202 apps)
11:25:35 CPU %user %nice %system %iowait %steal %idle
11:25:45 all 17.98 0.00 22.45 0.00 0.00 59.57

Processor load after stopping session(average value of 10 sec, with around 1497 apps)
11:25:46 CPU %user %nice %system %iowait %steal %idle
11:25:56 all 10.71 0.00 19.53 0.00 0.00 69.76

cat /cluster/temp/deleteme.log | grep -c testapp100_hightraf:HundredPerSec
actualNumOfHits = 716716
expectedNumOfHits = 1000000 +- 200000
test/LttngGlobalBuffer.cc:1988: Failure
Value of: oper.compareNumOfHit_vs_NumOfLine(grepToCountNumOfHit, durationOfActiveSession)
Actual: false
Expected: true
[ FAILED ] LttngGlobalBufferTest.LTTNGgbf_021load_1000ps_App100ps_HundredPerSec_ShortLifeSpan_multipleInactiveSession (106391 ms)
[----------] 1 test from LttngGlobalBufferTest (106391 ms total)

[----------] Global test environment tear-down
[==========] 1 test from 1 test case ran. (106392 ms total)
[ PASSED ] 0 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] LttngGlobalBufferTest.LTTNGgbf_021load_1000ps_App100ps_HundredPerSec_ShortLifeSpan_multipleInactiveSession

1 FAILED TEST
[SC-1:Node16 Mon Jun 10 11:26:15/cluster/temp/tdlt/SDP/EA_jun09am] # ps auxwwwf | head -n 1; ps auxwwwf|grep lttng
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 1058 0.0 0.0 4252 568 pts/1 S+ 11:26 0:00 | \_ grep lttng
root 12386 12.0 0.4 295076 115552 ? Ssl 11:21 0:33 lttng-sessiond -d
root 9529 0.2 0.0 146128 3252 ? Sl 11:24 0:00 \_ lttng-consumerd --quiet -u --consumerd-cmd-sock /var/run/lttng/ustconsumerd64/command --consumerd-err-sock /var/run/lttng/ustconsumerd64/error
[SC-1:Node16 Mon Jun 10 11:26:18/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:26:32/cluster/temp/tdlt/SDP/EA_jun09am] # ps auxwwwf | head -n 1; ps auxwwwf|grep lttng
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 1076 0.0 0.0 4252 572 pts/1 S+ 11:26 0:00 | \_ grep lttng
root 12386 11.4 0.4 295076 115552 ? Ssl 11:21 0:33 lttng-sessiond -d
root 9529 0.1 0.0 146128 3252 ? Sl 11:24 0:00 \_ lttng-consumerd --quiet -u --consumerd-cmd-sock /var/run/lttng/ustconsumerd64/command --consumerd-err-sock /var/run/lttng/ustconsumerd64/error
[SC-1:Node16 Mon Jun 10 11:26:33/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:26:35/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:26:35/cluster/temp/tdlt/SDP/EA_jun09am] # ps auxwwwf | head -n 1; ps auxwwwf|grep lttng
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 1096 0.0 0.0 4252 572 pts/1 S+ 11:26 0:00 | \_ grep lttng
root 12386 10.6 0.4 295076 115552 ? Ssl 11:21 0:33 lttng-sessiond -d
root 9529 0.1 0.0 146128 3252 ? Sl 11:24 0:00 \_ lttng-consumerd --quiet -u --consumerd-cmd-sock /var/run/lttng/ustconsumerd64/command --consumerd-err-sock /var/run/lttng/ustconsumerd64/error
[SC-1:Node16 Mon Jun 10 11:26:53/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:27:38/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:27:39/cluster/temp/tdlt/SDP/EA_jun09am] # ps auxwwwf | head -n 1; ps auxwwwf|grep lttng
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 1146 0.0 0.0 4252 572 pts/1 S+ 11:27 0:00 | \_ grep lttng
root 12386 9.3 0.4 295076 115552 ? Ssl 11:21 0:33 lttng-sessiond -d
root 9529 0.1 0.0 146128 3252 ? Sl 11:24 0:00 \_ lttng-consumerd --quiet -u --consumerd-cmd-sock /var/run/lttng/ustconsumerd64/command --consumerd-err-sock /var/run/lttng/ustconsumerd64/error
[SC-1:Node16 Mon Jun 10 11:27:40/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:27:41/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:27:41/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:27:41/cluster/temp/tdlt/SDP/EA_jun09am] # pkill sessiond
[SC-1:Node16 Mon Jun 10 11:27:45/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:27:46/cluster/temp/tdlt/SDP/EA_jun09am] # vi README
babeltrace : 9eaf254 Version 1.0.3
tools : 7ac8766 (HEAD, Apply_fix_for_bug539) Apply bug539 patch (from bug539 update #13)
cfa9a5a (HEAD, origin/master, origin/HEAD) Fix: poll compat layer reallocation new size
ust : 844a160 (HEAD, origin/stable-2.2) Fix: liblttng-ust process startup hang....
rcu : 264716f (HEAD, origin/stable-0.7, stable-0.7) Fix: Use a filled signal mask to disable all signals
~
~
~
~
~
~
~
~
~
~
~
~
~
~
~
~
~
~
~
~
~
"README" 5L, 440C written
[SC-1:Node16 Mon Jun 10 11:34:08/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:36:16/cluster/temp/tdlt/SDP/EA_jun09am] # ps auxwwwf | head -n 1; ps auxwwwf|grep lttng
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 1740 0.0 0.0 4252 572 pts/1 S+ 11:36 0:00 | \_ grep lttng
root 1209 0.0 0.0 150832 900 ? Ssl 11:27 0:00 lttng-sessiond -d
[SC-1:Node16 Mon Jun 10 11:36:25/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:36:25/cluster/temp/tdlt/SDP/EA_jun09am] # ps auxwwwf | head -n 1; ps auxwwwf|grep lttng
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 1756 0.0 0.0 4252 572 pts/1 S+ 11:36 0:00 | \_ grep lttng
root 1209 0.0 0.0 150832 900 ? Ssl 11:27 0:00 lttng-sessiond -d
[SC-1:Node16 Mon Jun 10 11:36:38/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:36:39/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:36:39/cluster/temp/tdlt/SDP/EA_jun09am] # for a in $(seq 1 40); do (for n in $(seq 1 100); do (/home/test_apps/TestApp_100perSecOnly 3 np > /dev/null &); done; usleep 200000); done &
[1] 1771
[SC-1:Node16 Mon Jun 10 11:36:53/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:36:59/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:37:01/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:37:03/cluster/temp/tdlt/SDP/EA_jun09am] #
[1]+ Done for a in $(seq 1 40);
do
( for n in $(seq 1 100);
do
( /home/test_apps/TestApp_100perSecOnly 3 np > /dev/null & );
done; usleep 200000 );
done
[SC-1:Node16 Mon Jun 10 11:37:04/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:37:05/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:37:06/cluster/temp/tdlt/SDP/EA_jun09am] # ps -e |grep -c TestApp
0
[SC-1:Node16 Mon Jun 10 11:37:12/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:37:12/cluster/temp/tdlt/SDP/EA_jun09am] # for a in $(seq 1 40); do (for n in $(seq 1 100); do (/home/test_apps/TestApp_100perSecOnly 3 np > /dev/null &); done; [SC-1:Node16 Mon Jun 10 11:37:12/cluster/temp/tdlt/SDP/EA_jun09am] # ps auxwwwf | head -n 1; ps auxwwwf|grep lttng
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 18103 0.0 0.0 4252 572 pts/1 S+ 11:37 0:00 | \_ grep lttng
root 1209 0.1 0.0 197980 12540 ? Ssl 11:27 0:00 lttng-sessiond -d
[SC-1:Node16 Mon Jun 10 11:37:16/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:37:19/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:37:19/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 11:37:20/cluster/temp/tdlt/SDP/EA_jun09am] #
(5-5/5)