Project

General

Profile

Bug #539 » Jun10_retest.log

terminal log when the above test was carried out (update #14) - Tan le tran, 06/10/2013 07:42 AM

 
[SC-1:Node16 Mon Jun 10 07:17:08/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 07:17:08/cluster/temp/tdlt/SDP/EA_jun09am] # pkill sessiond
[SC-1:Node16 Mon Jun 10 07:18:46/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 07:18:47/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 18586 0.0 0.0 4252 572 pts/1 S+ 07:18 0:00 \_ grep lttng
[SC-1:Node16 Mon Jun 10 07:18:48/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 07:18:50/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 07:18:50/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 07:18:50/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 18606 0.0 0.0 4252 572 pts/1 S+ 07:18 0:00 \_ grep lttng
root 18591 0.0 0.0 85296 912 ? Ssl 07:18 0:00 lttng-sessiond -d
[SC-1:Node16 Mon Jun 10 07:18:52/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 07:18:56/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 18616 0.0 0.0 4252 572 pts/1 S+ 07:18 0:00 \_ grep lttng
root 18591 0.0 0.0 85296 912 ? Ssl 07:18 0:00 lttng-sessiond -d
[SC-1:Node16 Mon Jun 10 07:18:57/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 07:18:58/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 07:18:59/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 07:18:59/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 07:18:59/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 07:18:59/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 18726 0.0 0.0 4252 572 pts/1 S+ 07:20 0:00 \_ grep lttng
root 18591 0.0 0.0 85296 912 ? Ssl 07:18 0:00 lttng-sessiond -d
[SC-1:Node16 Mon Jun 10 07:20:50/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 07:20:52/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] 18735
[SC-1:Node16 Mon Jun 10 07:20:56/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 07:20:57/cluster/temp/tdlt/SDP/EA_jun09am] # ps -e |grep -c |TestApp
-bash: TestApp: command not found
Usage: grep [OPTION]... PATTERN [FILE]...
Try `grep --help' for more information.
[SC-1:Node16 Mon Jun 10 07:21:04/cluster/temp/tdlt/SDP/EA_jun09am] # ps -e |grep -c TestApp
400
[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 07:21:08/cluster/temp/tdlt/SDP/EA_jun09am] # ps -e |grep -c TestApp
0
[SC-1:Node16 Mon Jun 10 07:21:12/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 07:21:15/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 07:21: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 2478 0.0 0.0 4252 572 pts/1 S+ 07:21 0:00 \_ grep lttng
root 18591 0.4 0.0 164256 7272 ? Ssl 07:18 0:00 lttng-sessiond -d
[SC-1:Node16 Mon Jun 10 07:21:19/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 2490 0.0 0.0 4252 572 pts/1 S+ 07:21 0:00 \_ grep lttng
root 18591 0.4 0.0 164256 7272 ? Ssl 07:18 0:00 lttng-sessiond -d
[SC-1:Node16 Mon Jun 10 07:21:25/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 07:21:26/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 07:21:26/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 07:21:26/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 07:21:47/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 07:21:48/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 07:21:48/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 07:21:48/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 07:21:48/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 07:21:48/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 07:21:49/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)
07:22:44 CPU %user %nice %system %iowait %steal %idle
07:22:47 all 0.00 0.00 0.00 0.00 0.00 100.00

Processor load after launching apps(average value of 10 sec, with around 991 apps)
07:22:52 CPU %user %nice %system %iowait %steal %idle
07:23:02 all 7.70 0.00 14.59 0.02 0.00 77.69

Processor load after session-1 created (still inactive)(average value of 10 sec, with around 902 apps)
07:23:04 CPU %user %nice %system %iowait %steal %idle
07:23:14 all 8.48 0.00 16.12 0.00 0.00 75.40

Processor load after session dummy1 created (still inactive)(average value of 10 sec, with around 1502 apps)
07:23:16 CPU %user %nice %system %iowait %steal %idle
07:23:26 all 9.39 0.00 17.58 0.00 0.00 73.03

Processor load after session dummy2 created (still inactive)(average value of 10 sec, with around 1202 apps)
07:23:27 CPU %user %nice %system %iowait %steal %idle
07:23:37 all 10.09 0.00 18.95 0.01 0.00 70.95

Processor load after session dummy3 created (still inactive)(average value of 10 sec, with around 1117 apps)
07:23:39 CPU %user %nice %system %iowait %steal %idle
07:23:49 all 11.13 0.00 20.07 0.00 0.00 68.80

Processor load after activating the session(average value of 10 sec, with around 1401 apps)
07:23:49 CPU %user %nice %system %iowait %steal %idle
07:23:59 all 18.77 0.00 22.22 0.00 0.00 59.01

Processor load after stopping session(average value of 10 sec, with around 902 apps)
07:24:00 CPU %user %nice %system %iowait %steal %idle
07:24:10 all 10.51 0.00 19.36 0.00 0.00 70.13

cat /cluster/temp/deleteme.log | grep -c testapp100_hightraf:HundredPerSec
actualNumOfHits = 745992
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 (106630 ms)
[----------] 1 test from LttngGlobalBufferTest (106630 ms total)

[----------] Global test environment tear-down
[==========] 1 test from 1 test case ran. (106630 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 07:24:30/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 22170 0.0 0.0 4252 568 pts/1 S+ 07:24 0:00 \_ grep lttng
root 18591 9.7 0.4 303824 110940 ? Ssl 07:18 0:33 lttng-sessiond -d
root 31702 0.2 0.0 146260 1256 ? Sl 07:23 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 07:24:34/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 07:24:36/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 22176 0.0 0.0 4252 572 pts/1 S+ 07:24 0:00 \_ grep lttng
root 18591 9.6 0.4 303824 110940 ? Ssl 07:18 0:33 lttng-sessiond -d
root 31702 0.2 0.0 146260 1256 ? Sl 07:23 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 07:24:38/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 07:24:39/cluster/temp/tdlt/SDP/EA_jun09am] # ps -ef |grep -c TestApp
1
[SC-1:Node16 Mon Jun 10 07:24:49/cluster/temp/tdlt/SDP/EA_jun09am] # ps -e |grep -c TestApp
0
[SC-1:Node16 Mon Jun 10 07:24:53/cluster/temp/tdlt/SDP/EA_jun09am] # lttng list
Currently no available tracing session
[SC-1:Node16 Mon Jun 10 07:24:58/cluster/temp/tdlt/SDP/EA_jun09am] # lttng list -u
UST events:
-------------
None

[SC-1:Node16 Mon Jun 10 07:25:00/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 07:25:01/cluster/temp/tdlt/SDP/EA_jun09am] # more README
babeltrace : 9eaf254 Version 1.0.3
tools : 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....
userspace : 264716f (HEAD, origin/stable-0.7, stable-0.7) Fix: Use a filled signal mask to disable all signals
[SC-1:Node16 Mon Jun 10 07:25:24/cluster/temp/tdlt/SDP/EA_jun09am] #
[SC-1:Node16 Mon Jun 10 07:35:41/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 22841 0.0 0.0 4252 568 pts/1 S+ 07:35 0:00 \_ grep lttng
root 18591 3.3 0.4 303824 112964 ? Ssl 07:18 0:33 lttng-sessiond -d
root 31702 0.0 0.0 146260 1256 ? Sl 07:23 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 07:35:45/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 22851 0.0 0.0 4252 568 pts/1 S+ 07:35 0:00 \_ grep lttng
root 18591 3.2 0.4 303824 112964 ? Ssl 07:18 0:33 lttng-sessiond -d
root 31702 0.0 0.0 146260 1256 ? Sl 07:23 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 07:35:53/cluster/temp/tdlt/SDP/EA_jun09am] #

(3-3/5)