latencytop kills volanomark throughput. yawn?

[Mike Galbraith]

Greetings list,

The moral of this story is probably "don't do that", but...

While doing some scheduler testing recently, I ran volanomark, and
accidentally left latencytop running.  The results were decidedly
un-good, and the reason appears to be that MUCH time is spent crawling
over a list of (106 loaded) modules.

	-Mike
2.6.25-smp
ulimit -Sn = 1024


/usr/bin/java -server -Xmx64m -Dinstall.root=. -Dcatalina.home=. -cp .:lib/bootstrap.jar:lib/catalina.jar:lib/naming-common.jar:lib/naming-resources.jar:lib/servlet.jar:lib/servlets-common.jar:lib/servlets-default.jar:lib/volanochat-server.jar:lib/xerces.jar COM.volano.Main

VolanoChat(TM) Server Version 2.5.0.9
Copyright (C) 1996-2002 Volano LLC.  All rights reserved.
Loading server properties from "/root/vmark2.5.0.9/conf/properties.txt".
marge:8000 (127.0.0.2:8000) VolanoChatPro - unlimited connections.
ulimit -Sn = 1024


/usr/bin/java -server -Xmx64m -Dinstall.root=. -Dcatalina.home=. -cp .:lib/bootstrap.jar:lib/catalina.jar:lib/naming-common.jar:lib/naming-resources.jar:lib/servlet.jar:lib/servlets-common.jar:lib/servlets-default.jar:lib/volanochat-server.jar:lib/xerces.jar COM.volano.Mark -run -count 2500

VolanoMark(TM) Benchmark Version 2.5.0.9
Copyright (C) 1996-2002 Volano LLC.  All rights reserved.
Creating room number 1 ...
20 connections so far.
Creating room number 2 ...
40 connections so far.
Creating room number 3 ...
60 connections so far.
Creating room number 4 ...
80 connections so far.
Creating room number 5 ...
100 connections so far.
Creating room number 6 ...
120 connections so far.
Creating room number 7 ...
140 connections so far.
Creating room number 8 ...
160 connections so far.
Creating room number 9 ...
180 connections so far.
Creating room number 10 ...
200 connections so far.
Java heap:  4225 KB in use, 11968 KB available (35% in use).
Running the test ...
Test complete.

VolanoMark version = 2.5.0.9
Messages sent      = 500000
Messages received  = 9500000
Total messages     = 10000000
Elapsed time       = 256.251 seconds
Average throughput = 39024 messages per second
VolanoMark(TM) Benchmark Version 2.5.0.9
Copyright (C) 1996-2002 Volano LLC.  All rights reserved.
Creating room number 1 ...
20 connections so far.
Creating room number 2 ...
40 connections so far.
Creating room number 3 ...
60 connections so far.
Creating room number 4 ...
80 connections so far.
Creating room number 5 ...
100 connections so far.
Creating room number 6 ...
120 connections so far.
Creating room number 7 ...
140 connections so far.
Creating room number 8 ...
160 connections so far.
Creating room number 9 ...
180 connections so far.
Creating room number 10 ...
200 connections so far.
Java heap:  4055 KB in use, 11968 KB available (34% in use).
Running the test ...
Test complete.

VolanoMark version = 2.5.0.9
Messages sent      = 500000
Messages received  = 9500000
Total messages     = 10000000
Elapsed time       = 260.755 seconds
Average throughput = 38350 messages per second
VolanoMark(TM) Benchmark Version 2.5.0.9
Copyright (C) 1996-2002 Volano LLC.  All rights reserved.
Creating room number 1 ...
20 connections so far.
Creating room number 2 ...
40 connections so far.
Creating room number 3 ...
60 connections so far.
Creating room number 4 ...
80 connections so far.
Creating room number 5 ...
100 connections so far.
Creating room number 6 ...
120 connections so far.
Creating room number 7 ...
140 connections so far.
Creating room number 8 ...
160 connections so far.
Creating room number 9 ...
180 connections so far.
Creating room number 10 ...
200 connections so far.
Java heap:  4079 KB in use, 11968 KB available (34% in use).
Running the test ...
Test complete.

VolanoMark version = 2.5.0.9
Messages sent      = 500000
Messages received  = 9500000
Total messages     = 10000000
Elapsed time       = 257.859 seconds
Average throughput = 38781 messages per second
CPU: Core 2, speed 2400 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (Unhalted core cycles) count 100000
Samples on CPU 0
Samples on CPU 1
Samples on CPU 2
Samples on CPU 3
vma      samples  %        samples  %        samples  %        samples  %        symbol name
ffffffff80250ac3 7275309  75.2127  7484800  75.2938  7470398  75.2679  7496386  75.3165  __module_text_address
ffffffff80242f08 153617    1.5881  159017    1.5996  157306    1.5849  158765    1.5951  core_kernel_text
ffffffff80242f77 137870    1.4253  146199    1.4707  145779    1.4688  146526    1.4722  __kernel_text_address
ffffffff8040fa80 131667    1.3612  134133    1.3493  133196    1.3420  133695    1.3432  schedule
2.6.25-smp
ulimit -Sn = 1024


/usr/bin/java -server -Xmx64m -Dinstall.root=. -Dcatalina.home=. -cp .:lib/bootstrap.jar:lib/catalina.jar:lib/naming-common.jar:lib/naming-resources.jar:lib/servlet.jar:lib/servlets-common.jar:lib/servlets-default.jar:lib/volanochat-server.jar:lib/xerces.jar COM.volano.Main

VolanoChat(TM) Server Version 2.5.0.9
Copyright (C) 1996-2002 Volano LLC.  All rights reserved.
Loading server properties from "/root/vmark2.5.0.9/conf/properties.txt".
marge:8000 (127.0.0.2:8000) VolanoChatPro - unlimited connections.
Apache Tomcat/4.0.3
ulimit -Sn = 1024


/usr/bin/java -server -Xmx64m -Dinstall.root=. -Dcatalina.home=. -cp .:lib/bootstrap.jar:lib/catalina.jar:lib/naming-common.jar:lib/naming-resources.jar:lib/servlet.jar:lib/servlets-common.jar:lib/servlets-default.jar:lib/volanochat-server.jar:lib/xerces.jar COM.volano.Mark -run -count 2500

VolanoMark(TM) Benchmark Version 2.5.0.9
Copyright (C) 1996-2002 Volano LLC.  All rights reserved.
Creating room number 1 ...
20 connections so far.
Creating room number 2 ...
40 connections so far.
Creating room number 3 ...
60 connections so far.
Creating room number 4 ...
80 connections so far.
Creating room number 5 ...
100 connections so far.
Creating room number 6 ...
120 connections so far.
Creating room number 7 ...
140 connections so far.
Creating room number 8 ...
160 connections so far.
Creating room number 9 ...
180 connections so far.
Creating room number 10 ...
200 connections so far.
Java heap:  4103 KB in use, 11968 KB available (34% in use).
Running the test ...
Test complete.

VolanoMark version = 2.5.0.9
Messages sent      = 500000
Messages received  = 9500000
Total messages     = 10000000
Elapsed time       = 80.53 seconds
Average throughput = 124177 messages per second
VolanoMark(TM) Benchmark Version 2.5.0.9
Copyright (C) 1996-2002 Volano LLC.  All rights reserved.
Creating room number 1 ...
20 connections so far.
Creating room number 2 ...
40 connections so far.
Creating room number 3 ...
60 connections so far.
Creating room number 4 ...
80 connections so far.
Creating room number 5 ...
100 connections so far.
Creating room number 6 ...
120 connections so far.
Creating room number 7 ...
140 connections so far.
Creating room number 8 ...
160 connections so far.
Creating room number 9 ...
180 connections so far.
Creating room number 10 ...
200 connections so far.
Java heap:  4066 KB in use, 11968 KB available (34% in use).
Running the test ...
Test complete.

VolanoMark version = 2.5.0.9
Messages sent      = 500000
Messages received  = 9500000
Total messages     = 10000000
Elapsed time       = 82.893 seconds
Average throughput = 120637 messages per second
VolanoMark(TM) Benchmark Version 2.5.0.9
Copyright (C) 1996-2002 Volano LLC.  All rights reserved.
Creating room number 1 ...
20 connections so far.
Creating room number 2 ...
40 connections so far.
Creating room number 3 ...
60 connections so far.
Creating room number 4 ...
80 connections so far.
Creating room number 5 ...
100 connections so far.
Creating room number 6 ...
120 connections so far.
Creating room number 7 ...
140 connections so far.
Creating room number 8 ...
160 connections so far.
Creating room number 9 ...
180 connections so far.
Creating room number 10 ...
200 connections so far.
Java heap:  4066 KB in use, 11968 KB available (34% in use).
Running the test ...
Test complete.

VolanoMark version = 2.5.0.9
Messages sent      = 500000
Messages received  = 9500000
Total messages     = 10000000
Elapsed time       = 83.045 seconds
Average throughput = 120417 messages per second
CPU: Core 2, speed 2400 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (Unhalted core cycles) count 100000
Samples on CPU 0
Samples on CPU 1
Samples on CPU 2
Samples on CPU 3
vma      samples  %        samples  %        samples  %        samples  %        symbol name
ffffffff8040fa80 101885    7.3225  105675    7.3536  104738    7.3105  104360    7.2758  schedule
ffffffff8020a872 38079     2.7367  38675     2.6913  38259     2.6704  37778     2.6338  __switch_to
ffffffff803cd4a1 37283     2.6795  37872     2.6354  38264     2.6708  38416     2.6783  tcp_sendmsg
ffffffff803bce72 34238     2.4607  35386     2.4624  35458     2.4749  35369     2.4659  nf_iterate
ffffffff803d6dff 33708     2.4226  34382     2.3925  35210     2.4576  34770     2.4241  tcp_transmit_skb
ffffffff8022b435 32216     2.3154  32801     2.2825  32441     2.2643  32561     2.2701  task_rq_lock
ffffffff8041019b 30984     2.2268  32897     2.2892  33092     2.3098  33149     2.3111  thread_return
ffffffff80212710 28698     2.0625  29613     2.0607  29925     2.0887  30017     2.0927  native_read_tsc
ffffffff803a2c34 27350     1.9656  28071     1.9534  27624     1.9281  27601     1.9243  netif_rx
ffffffff803dcd35 27329     1.9641  27798     1.9344  28084     1.9602  28233     1.9683  tcp_v4_rcv
ffffffff802ffbe0 26391     1.8967  30879     2.1488  29893     2.0865  31739     2.2128  copy_user_generic_string
ffffffff803c6bb7 24902     1.7897  25270     1.7585  24637     1.7196  25099     1.7499  ip_queue_xmit
ffffffff8039dc47 24866     1.7871  26068     1.8140  25733     1.7961  25869     1.8035  skb_release_all
ffffffff8028db6b 24765     1.7799  25006     1.7401  25154     1.7557  25707     1.7922  fget_light
ffffffff80228378 23550     1.6925  24488     1.7040  23946     1.6714  24154     1.6840  __enqueue_entity
ffffffff803c9bd6 23270     1.6724  23490     1.6346  23264     1.6238  23375     1.6297  __inet_lookup_established
ffffffff8022f3a1 19656     1.4127  19080     1.3277  19152     1.3368  19208     1.3391  select_task_rq_fair
ffffffff803ce391 19498     1.4013  20477     1.4249  20394     1.4235  20409     1.4229  tcp_recvmsg
ffffffff803d1680 18634     1.3392  19414     1.3510  19538     1.3637  19178     1.3371  tcp_ack
ffffffff8023793d 18106     1.3013  18399     1.2803  18285     1.2763  18610     1.2975  local_bh_enable
ffffffff8020be00 17235     1.2387  17809     1.2393  17673     1.2335  17890     1.2473  system_call
ffffffff803a53f1 16076     1.1554  16560     1.1524  16230     1.1328  16464     1.1478  process_backlog
ffffffff803d5c26 15110     1.0860  16067     1.1180  15661     1.0931  15441     1.0765  tcp_rcv_established
ffffffff803d8892 15045     1.0813  15420     1.0730  15406     1.0753  15560     1.0848  __tcp_push_pending_frames
ffffffff80228683 14623     1.0510  14960     1.0410  14816     1.0341  14830     1.0339  hrtick_start_fair
ffffffff80212510 14567     1.0469  14818     1.0311  14922     1.0415  14979     1.0443  native_sched_clock