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/logs/125.runsolver.smart smart --config-file=/home/cbse/var/lib/smart/config remove libtunepimp-bin kdegames-card-data gnupg2 librsvg2-dev python2.3 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 [startup+0 s] /proc/loadavg: 1.03 1.01 1.00 2/53 22801 /proc/meminfo: memFree=357112/1022884 swapFree=0/0 [pid=22801] ppid=22800 vsize=3152 CPUtime=0 /proc/22801/stat : 22801 (runsolver) R 22800 2806 2806 34818 2806 4202560 0 0 0 0 0 0 0 0 20 0 1 0 13105412 3227648 33 18446744073709551615 134512640 134586868 4288931008 4288929056 4152099888 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/22801/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.112071 s] /proc/loadavg: 1.03 1.01 1.00 2/53 22801 /proc/meminfo: memFree=357112/1022884 swapFree=0/0 [pid=22801] ppid=22800 vsize=111532 CPUtime=0.1 /proc/22801/stat : 22801 (smart) R 22800 22801 2806 34818 2806 4202496 7958 0 0 0 7 3 0 0 20 0 1 0 13105412 114208768 6677 18446744073709551615 4194304 6763684 140736508636368 140736508631384 5039824 0 0 16781312 2 0 0 0 17 0 0 0 0 0 0 /proc/22801/statm: 27883 6677 1043 628 0 5466 0 Current children cumulated CPU time (s) 0.1 Current children cumulated vsize (KiB) 111532 [startup+0.200252 s] /proc/loadavg: 1.03 1.01 1.00 2/53 22801 /proc/meminfo: memFree=357112/1022884 swapFree=0/0 [pid=22801] ppid=22800 vsize=131308 CPUtime=0.19 /proc/22801/stat : 22801 (smart) R 22800 22801 2806 34818 2806 4202496 14363 0 0 0 15 4 0 0 20 0 1 0 13105412 134459392 11545 18446744073709551615 4194304 6763684 140736508636368 140736508631384 5520626 0 0 16781312 2 0 0 0 17 0 0 0 0 0 0 /proc/22801/statm: 32827 11545 1043 628 0 10410 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 131308 [startup+0.300244 s] /proc/loadavg: 1.03 1.01 1.00 2/53 22801 /proc/meminfo: memFree=357112/1022884 swapFree=0/0 [pid=22801] ppid=22800 vsize=135820 CPUtime=0.29 /proc/22801/stat : 22801 (smart) R 22800 22801 2806 34818 2806 4202496 19193 413 0 0 23 6 0 0 20 0 1 0 13105412 139079680 11726 18446744073709551615 4194304 6763684 140736508636368 140736508632360 5763084 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/22801/statm: 33955 11726 1058 628 0 10508 0 Current children cumulated CPU time (s) 0.29 Current children cumulated vsize (KiB) 135820 [startup+0.700193 s] /proc/loadavg: 1.03 1.01 1.00 2/53 22801 /proc/meminfo: memFree=357112/1022884 swapFree=0/0 [pid=22801] ppid=22800 vsize=181572 CPUtime=0.68 /proc/22801/stat : 22801 (smart) R 22800 22801 2806 34818 2806 4202496 34149 413 0 0 58 10 0 0 20 0 1 0 13105412 185929728 23108 18446744073709551615 4194304 6763684 140736508636368 140736508632360 4531156 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/22801/statm: 45393 23108 1059 628 0 21946 0 Current children cumulated CPU time (s) 0.68 Current children cumulated vsize (KiB) 181572 [startup+1.5002 s] /proc/loadavg: 1.03 1.01 1.00 2/54 22804 /proc/meminfo: memFree=221200/1022884 swapFree=0/0 [pid=22801] ppid=22800 vsize=285836 CPUtime=1.48 /proc/22801/stat : 22801 (smart) R 22800 22801 2806 34818 2806 4202496 66386 413 0 0 128 20 0 0 20 0 1 0 13105412 292696064 49196 18446744073709551615 4194304 6763684 140736508636368 140736508632360 5518020 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/22801/statm: 71459 49196 1059 628 0 48012 0 Current children cumulated CPU time (s) 1.48 Current children cumulated vsize (KiB) 285836 [startup+3.1002 s] /proc/loadavg: 1.03 1.01 1.00 2/54 22804 /proc/meminfo: memFree=154364/1022884 swapFree=0/0 [pid=22801] ppid=22800 vsize=332368 CPUtime=3.07 /proc/22801/stat : 22801 (smart) R 22800 22801 2806 34818 2806 4202496 90342 413 0 0 281 26 0 0 20 0 1 0 13105412 340344832 60831 18446744073709551615 4194304 6763684 140736508636368 140736508632408 5743575 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/22801/statm: 83092 60831 1068 628 0 59645 0 Current children cumulated CPU time (s) 3.07 Current children cumulated vsize (KiB) 332368 [startup+6.3002 s] /proc/loadavg: 1.03 1.01 1.00 2/54 22804 /proc/meminfo: memFree=106376/1022884 swapFree=0/0 [pid=22801] ppid=22800 vsize=343324 CPUtime=6.26 /proc/22801/stat : 22801 (smart) R 22800 22801 2806 34818 2806 4202496 93122 413 0 0 599 27 0 0 20 0 1 0 13105412 351563776 63600 18446744073709551615 4194304 6763684 140736508636368 140736508633320 139642037677786 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/22801/statm: 85831 63600 1073 628 0 62384 0 Current children cumulated CPU time (s) 6.26 Current children cumulated vsize (KiB) 343324 [startup+12.7002 s] /proc/loadavg: 1.02 1.01 1.00 2/54 22804 /proc/meminfo: memFree=106252/1022884 swapFree=0/0 [pid=22801] ppid=22800 vsize=343324 CPUtime=12.63 /proc/22801/stat : 22801 (smart) R 22800 22801 2806 34818 2806 4202496 93124 413 0 0 1236 27 0 0 20 0 1 0 13105412 351563776 63600 18446744073709551615 4194304 6763684 140736508636368 140736508633320 139642037677920 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/22801/statm: 85831 63600 1073 628 0 62384 0 Current children cumulated CPU time (s) 12.63 Current children cumulated vsize (KiB) 343324 [startup+25.5002 s] /proc/loadavg: 1.02 1.01 1.00 2/54 22804 /proc/meminfo: memFree=106252/1022884 swapFree=0/0 [pid=22801] ppid=22800 vsize=343324 CPUtime=25.38 /proc/22801/stat : 22801 (smart) R 22800 22801 2806 34818 2806 4202496 93128 413 0 0 2511 27 0 0 20 0 1 0 13105412 351563776 63600 18446744073709551615 4194304 6763684 140736508636368 140736508633320 139642037677786 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/22801/statm: 85831 63600 1073 628 0 62384 0 Current children cumulated CPU time (s) 25.38 Current children cumulated vsize (KiB) 343324 [startup+51.1002 s] /proc/loadavg: 1.01 1.01 1.00 2/54 22804 /proc/meminfo: memFree=106128/1022884 swapFree=0/0 [pid=22801] ppid=22800 vsize=343324 CPUtime=50.88 /proc/22801/stat : 22801 (smart) R 22800 22801 2806 34818 2806 4202496 93128 413 0 0 5061 27 0 0 20 0 1 0 13105412 351563776 63600 18446744073709551615 4194304 6763684 140736508636368 140736508633320 139642037677786 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/22801/statm: 85831 63600 1073 628 0 62384 0 Current children cumulated CPU time (s) 50.88 Current children cumulated vsize (KiB) 343324 [startup+102.3 s] /proc/loadavg: 1.00 1.00 1.00 2/54 22804 /proc/meminfo: memFree=106128/1022884 swapFree=0/0 [pid=22801] ppid=22800 vsize=343324 CPUtime=101.89 /proc/22801/stat : 22801 (smart) R 22800 22801 2806 34818 2806 4202496 93128 413 0 0 10162 27 0 0 20 0 1 0 13105412 351563776 63600 18446744073709551615 4194304 6763684 140736508636368 140736508633320 139642037677920 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/22801/statm: 85831 63600 1073 628 0 62384 0 Current children cumulated CPU time (s) 101.89 Current children cumulated vsize (KiB) 343324 [startup+162.3 s] /proc/loadavg: 1.00 1.00 1.00 2/54 22804 /proc/meminfo: memFree=106004/1022884 swapFree=0/0 [pid=22801] ppid=22800 vsize=343324 CPUtime=161.66 /proc/22801/stat : 22801 (smart) R 22800 22801 2806 34818 2806 4202496 93128 413 0 0 16139 27 0 0 20 0 1 0 13105412 351563776 63600 18446744073709551615 4194304 6763684 140736508636368 140736508633320 139642037677786 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/22801/statm: 85831 63600 1073 628 0 62384 0 Current children cumulated CPU time (s) 161.66 Current children cumulated vsize (KiB) 343324 [startup+222.303 s] /proc/loadavg: 1.00 1.00 1.00 2/54 22804 /proc/meminfo: memFree=106004/1022884 swapFree=0/0 [pid=22801] ppid=22800 vsize=343324 CPUtime=221.43 /proc/22801/stat : 22801 (smart) R 22800 22801 2806 34818 2806 4202496 93130 413 0 0 22116 27 0 0 20 0 1 0 13105412 351563776 63600 18446744073709551615 4194304 6763684 140736508636368 140736508633320 139642037681464 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/22801/statm: 85831 63600 1073 628 0 62384 0 Current children cumulated CPU time (s) 221.43 Current children cumulated vsize (KiB) 343324 [startup+282.3 s] /proc/loadavg: 1.00 1.00 1.00 2/54 22812 /proc/meminfo: memFree=105624/1022884 swapFree=0/0 [pid=22801] ppid=22800 vsize=343756 CPUtime=281.18 /proc/22801/stat : 22801 (smart) R 22800 22801 2806 34818 2806 4202496 93252 413 0 0 28091 27 0 0 20 0 1 0 13105412 352006144 63720 18446744073709551615 4194304 6763684 140736508636368 140736508545944 139642037677786 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/22801/statm: 85939 63720 1073 628 0 62492 0 Current children cumulated CPU time (s) 281.18 Current children cumulated vsize (KiB) 343756 Maximum wall clock time exceeded: sending signal-name then SIGKILL [startup+300 s] /proc/loadavg: 1.00 1.00 1.00 2/54 22812 /proc/meminfo: memFree=102772/1022884 swapFree=0/0 [pid=22801] ppid=22800 vsize=346492 CPUtime=298.81 /proc/22801/stat : 22801 (smart) R 22800 22801 2806 34818 2806 4202496 93936 413 0 0 29853 28 0 0 20 0 1 0 13105412 354807808 64404 18446744073709551615 4194304 6763684 140736508636368 140736508545944 139642037677840 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/22801/statm: 86623 64404 1073 628 0 63176 0 Current children cumulated CPU time (s) 298.81 Current children cumulated vsize (KiB) 346492 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 1.00 2/54 22812 /proc/meminfo: memFree=102772/1022884 swapFree=0/0 [pid=22801] ppid=22800 vsize=346492 CPUtime=298.81 /proc/22801/stat : 22801 (smart) R 22800 22801 2806 34818 2806 4202496 93936 413 0 0 29853 28 0 0 20 0 1 0 13105412 354807808 64404 18446744073709551615 4194304 6763684 140736508636368 140736508545944 139642037677840 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/22801/statm: 86623 64404 1073 628 0 63176 0 Current children cumulated CPU time (s) 298.81 Current children cumulated vsize (KiB) 346492 Child ended because it received signal 15 (SIGTERM) Real time (s): 300.028 CPU time (s): 298.847 CPU user time (s): 298.543 CPU system time (s): 0.304019 CPU usage (%): 99.6063 Max. virtual memory (cumulated for all children) (KiB): 346492 getrusage(RUSAGE_CHILDREN,...) data: user time used= 298.543 system time used= 0.304019 maximum resident set size= 257616 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 94349 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= 6 involuntary context switches= 4389 runsolver used 0.280017 second user time and 0.880055 second system time The end