runsolver Copyright (C) 2010 Olivier ROUSSEL This is runsolver version 3.2.9a (svn: 651) This program is distributed in the hope that it will be useful, but WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for more details. command line: runsolver -W 300 -M 1124 -w /home/cbse/results/sarge-etch-lenny-squeeze-sid/logs/162.runsolver.smart smart --config-file=/home/cbse/var/lib/smart/config remove mount kwordquiz libopencdk8 autoconf libxrender1 Enforcing wall clock limit (soft limit, will send signal-name then SIGKILL): 300 seconds Enforcing VSIZE limit (soft limit, will send signal-name then SIGKILL): 1150976 KiB Enforcing VSIZE limit (hard limit, stack expansion will fail with SIGSEGV, brk() and mmap() will return ENOMEM): 1202176 KiB Current StackSize limit: 8192 KiB [startup+0 s] /proc/loadavg: 1.00 1.00 0.98 2/53 32196 /proc/meminfo: memFree=379920/1022884 swapFree=0/0 [pid=32196] ppid=32195 vsize=26808 CPUtime=0 /proc/32196/stat : 32196 (smart) R 32195 32196 2806 34818 2806 4202496 604 0 0 0 0 0 0 0 20 0 1 0 19090217 27451392 496 18446744073709551615 4194304 6763684 140736480996592 140736480987128 5760889 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/32196/statm: 6702 496 368 628 0 161 0 [startup+0.130909 s] /proc/loadavg: 1.00 1.00 0.98 2/53 32196 /proc/meminfo: memFree=379920/1022884 swapFree=0/0 [pid=32196] ppid=32195 vsize=118964 CPUtime=0.12 /proc/32196/stat : 32196 (smart) R 32195 32196 2806 34818 2806 4202496 9771 0 0 0 8 4 0 0 20 0 1 0 19090217 121819136 8491 18446744073709551615 4194304 6763684 140736480996592 140736480991672 5255582 0 0 16781312 2 0 0 0 17 0 0 0 0 0 0 /proc/32196/statm: 29741 8491 1043 628 0 7324 0 Current children cumulated CPU time (s) 0.12 Current children cumulated vsize (KiB) 118964 [startup+0.200255 s] /proc/loadavg: 1.00 1.00 0.98 2/53 32196 /proc/meminfo: memFree=379920/1022884 swapFree=0/0 [pid=32196] ppid=32195 vsize=132848 CPUtime=0.19 /proc/32196/stat : 32196 (smart) R 32195 32196 2806 34818 2806 4202496 14824 0 0 0 13 6 0 0 20 0 1 0 19090217 136036352 12007 18446744073709551615 4194304 6763684 140736480996592 140736480991672 4364559 0 0 16781312 2 0 0 0 17 0 0 0 0 0 0 /proc/32196/statm: 33212 12007 1043 628 0 10795 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 132848 [startup+0.300248 s] /proc/loadavg: 1.00 1.00 0.98 2/53 32196 /proc/meminfo: memFree=379920/1022884 swapFree=0/0 [pid=32196] ppid=32195 vsize=136208 CPUtime=0.28 /proc/32196/stat : 32196 (smart) R 32195 32196 2806 34818 2806 4202496 21506 412 0 0 20 8 0 0 20 0 1 0 19090217 139476992 11828 18446744073709551615 4194304 6763684 140736480996592 140736480992568 5518020 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/32196/statm: 34052 11828 1058 628 0 10605 0 Current children cumulated CPU time (s) 0.28 Current children cumulated vsize (KiB) 136208 [startup+0.700187 s] /proc/loadavg: 1.00 1.00 0.98 2/53 32196 /proc/meminfo: memFree=379920/1022884 swapFree=0/0 [pid=32196] ppid=32195 vsize=186176 CPUtime=0.69 /proc/32196/stat : 32196 (smart) R 32195 32196 2806 34818 2806 4202496 35539 412 0 0 57 12 0 0 20 0 1 0 19090217 190644224 24260 18446744073709551615 4194304 6763684 140736480996592 140736480992648 5763084 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/32196/statm: 46544 24260 1059 628 0 23097 0 Current children cumulated CPU time (s) 0.69 Current children cumulated vsize (KiB) 186176 [startup+1.50018 s] /proc/loadavg: 1.00 1.00 0.98 2/54 32199 /proc/meminfo: memFree=238180/1022884 swapFree=0/0 [pid=32196] ppid=32195 vsize=289624 CPUtime=1.48 /proc/32196/stat : 32196 (smart) R 32195 32196 2806 34818 2806 4202496 67588 412 0 0 128 20 0 0 20 0 1 0 19090217 296574976 50161 18446744073709551615 4194304 6763684 140736480996592 140736480992648 140307527505410 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/32196/statm: 72406 50161 1059 628 0 48959 0 Current children cumulated CPU time (s) 1.48 Current children cumulated vsize (KiB) 289624 [startup+3.10019 s] /proc/loadavg: 1.00 1.00 0.98 2/54 32199 /proc/meminfo: memFree=114552/1022884 swapFree=0/0 [pid=32196] ppid=32195 vsize=348236 CPUtime=3.08 /proc/32196/stat : 32196 (smart) R 32195 32196 2806 34818 2806 4202496 94583 412 0 0 283 25 0 0 20 0 1 0 19090217 356593664 64836 18446744073709551615 4194304 6763684 140736480996592 140736480992632 140307527497363 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/32196/statm: 87059 64836 1068 628 0 63612 0 Current children cumulated CPU time (s) 3.08 Current children cumulated vsize (KiB) 348236 [startup+6.30019 s] /proc/loadavg: 1.00 1.00 0.98 2/54 32199 /proc/meminfo: memFree=106864/1022884 swapFree=0/0 [pid=32196] ppid=32195 vsize=365564 CPUtime=6.27 /proc/32196/stat : 32196 (smart) R 32195 32196 2806 34818 2806 4202496 98903 412 0 0 601 26 0 0 20 0 1 0 19090217 374337536 69145 18446744073709551615 4194304 6763684 140736480996592 140736480993544 140307545239258 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/32196/statm: 91391 69145 1073 628 0 67944 0 Current children cumulated CPU time (s) 6.27 Current children cumulated vsize (KiB) 365564 [startup+12.7002 s] /proc/loadavg: 1.00 1.00 0.98 2/54 32199 /proc/meminfo: memFree=106740/1022884 swapFree=0/0 [pid=32196] ppid=32195 vsize=365564 CPUtime=12.64 /proc/32196/stat : 32196 (smart) R 32195 32196 2806 34818 2806 4202496 98903 412 0 0 1238 26 0 0 20 0 1 0 19090217 374337536 69145 18446744073709551615 4194304 6763684 140736480996592 140736480993544 140307545239392 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/32196/statm: 91391 69145 1073 628 0 67944 0 Current children cumulated CPU time (s) 12.64 Current children cumulated vsize (KiB) 365564 [startup+25.5002 s] /proc/loadavg: 1.00 1.00 0.98 2/54 32199 /proc/meminfo: memFree=106740/1022884 swapFree=0/0 [pid=32196] ppid=32195 vsize=365564 CPUtime=25.39 /proc/32196/stat : 32196 (smart) R 32195 32196 2806 34818 2806 4202496 98908 412 0 0 2513 26 0 0 20 0 1 0 19090217 374337536 69145 18446744073709551615 4194304 6763684 140736480996592 140736480993544 140307545239278 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/32196/statm: 91391 69145 1073 628 0 67944 0 Current children cumulated CPU time (s) 25.39 Current children cumulated vsize (KiB) 365564 [startup+51.1002 s] /proc/loadavg: 1.00 1.00 0.98 2/54 32199 /proc/meminfo: memFree=106740/1022884 swapFree=0/0 [pid=32196] ppid=32195 vsize=365564 CPUtime=50.9 /proc/32196/stat : 32196 (smart) R 32195 32196 2806 34818 2806 4202496 98909 412 0 0 5064 26 0 0 20 0 1 0 19090217 374337536 69145 18446744073709551615 4194304 6763684 140736480996592 140736480993544 140307545239392 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/32196/statm: 91391 69145 1073 628 0 67944 0 Current children cumulated CPU time (s) 50.9 Current children cumulated vsize (KiB) 365564 [startup+102.3 s] /proc/loadavg: 1.00 1.00 0.98 2/54 32199 /proc/meminfo: memFree=106616/1022884 swapFree=0/0 [pid=32196] ppid=32195 vsize=365564 CPUtime=101.91 /proc/32196/stat : 32196 (smart) R 32195 32196 2806 34818 2806 4202496 98909 412 0 0 10165 26 0 0 20 0 1 0 19090217 374337536 69145 18446744073709551615 4194304 6763684 140736480996592 140736480993544 140307545239258 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/32196/statm: 91391 69145 1073 628 0 67944 0 Current children cumulated CPU time (s) 101.91 Current children cumulated vsize (KiB) 365564 [startup+162.3 s] /proc/loadavg: 1.00 1.00 0.98 2/54 32199 /proc/meminfo: memFree=106616/1022884 swapFree=0/0 [pid=32196] ppid=32195 vsize=365564 CPUtime=161.69 /proc/32196/stat : 32196 (smart) R 32195 32196 2806 34818 2806 4202496 98909 412 0 0 16143 26 0 0 20 0 1 0 19090217 374337536 69145 18446744073709551615 4194304 6763684 140736480996592 140736480993544 140307527491248 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/32196/statm: 91391 69145 1073 628 0 67944 0 Current children cumulated CPU time (s) 161.69 Current children cumulated vsize (KiB) 365564 [startup+222.303 s] /proc/loadavg: 1.00 1.00 0.98 2/54 32199 /proc/meminfo: memFree=106616/1022884 swapFree=0/0 [pid=32196] ppid=32195 vsize=365564 CPUtime=221.46 /proc/32196/stat : 32196 (smart) R 32195 32196 2806 34818 2806 4202496 98909 412 0 0 22120 26 0 0 20 0 1 0 19090217 374337536 69145 18446744073709551615 4194304 6763684 140736480996592 140736480993544 140307545239258 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/32196/statm: 91391 69145 1073 628 0 67944 0 Current children cumulated CPU time (s) 221.46 Current children cumulated vsize (KiB) 365564 [startup+282.3 s] /proc/loadavg: 1.00 1.00 0.98 2/54 32199 /proc/meminfo: memFree=106616/1022884 swapFree=0/0 [pid=32196] ppid=32195 vsize=365564 CPUtime=281.24 /proc/32196/stat : 32196 (smart) R 32195 32196 2806 34818 2806 4202496 98909 412 0 0 28098 26 0 0 20 0 1 0 19090217 374337536 69145 18446744073709551615 4194304 6763684 140736480996592 140736480993544 140307545239392 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/32196/statm: 91391 69145 1073 628 0 67944 0 Current children cumulated CPU time (s) 281.24 Current children cumulated vsize (KiB) 365564 Maximum wall clock time exceeded: sending signal-name then SIGKILL [startup+300 s] /proc/loadavg: 1.00 1.00 0.98 2/54 32199 /proc/meminfo: memFree=106616/1022884 swapFree=0/0 [pid=32196] ppid=32195 vsize=365564 CPUtime=298.87 /proc/32196/stat : 32196 (smart) R 32195 32196 2806 34818 2806 4202496 98909 412 0 0 29861 26 0 0 20 0 1 0 19090217 374337536 69145 18446744073709551615 4194304 6763684 140736480996592 140736480993544 140307545239258 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/32196/statm: 91391 69145 1073 628 0 67944 0 Current children cumulated CPU time (s) 298.87 Current children cumulated vsize (KiB) 365564 Sending Terminated to process tree (bottom up) Sleeping 2 seconds Solver just ended. Dumping a history of the last processes samples [startup+300 s] /proc/loadavg: 1.00 1.00 0.98 2/54 32199 /proc/meminfo: memFree=106616/1022884 swapFree=0/0 [pid=32196] ppid=32195 vsize=365564 CPUtime=298.87 /proc/32196/stat : 32196 (smart) R 32195 32196 2806 34818 2806 4202496 98909 412 0 0 29861 26 0 0 20 0 1 0 19090217 374337536 69145 18446744073709551615 4194304 6763684 140736480996592 140736480993544 140307545239258 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/32196/statm: 91391 69145 1073 628 0 67944 0 Current children cumulated CPU time (s) 298.87 Current children cumulated vsize (KiB) 365564 Child ended because it received signal 15 (SIGTERM) Real time (s): 300.025 CPU time (s): 298.903 CPU user time (s): 298.619 CPU system time (s): 0.284017 CPU usage (%): 99.6259 Max. virtual memory (cumulated for all children) (KiB): 365564 getrusage(RUSAGE_CHILDREN,...) data: user time used= 298.619 system time used= 0.284017 maximum resident set size= 276580 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 99321 page faults= 0 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 7 involuntary context switches= 4452 runsolver used 0.744046 second user time and 0.560035 second system time The end