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/logs/110.runsolver.smart smart --config-file=/home/cbse/var/lib/smart/config remove libvorbis-ocaml sed libgnomeprintui2.2-0 quanta-data libsvn0 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: 0.99 0.98 0.99 2/53 14472 /proc/meminfo: memFree=389332/1022884 swapFree=0/0 [pid=14472] ppid=14471 vsize=3152 CPUtime=0 /proc/14472/stat : 14472 (runsolver) R 14471 2806 2806 34818 2806 4202560 0 0 0 0 0 0 0 0 20 0 1 0 7785108 3227648 33 18446744073709551615 134512640 134586868 4289507520 4289505568 4152063024 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/14472/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.112931 s] /proc/loadavg: 0.99 0.98 0.99 2/53 14472 /proc/meminfo: memFree=389332/1022884 swapFree=0/0 [pid=14472] ppid=14471 vsize=113532 CPUtime=0.11 /proc/14472/stat : 14472 (smart) R 14471 14472 2806 34818 2806 4202496 8434 0 0 0 9 2 0 0 20 0 1 0 7785108 116256768 7154 18446744073709551615 4194304 6763684 140733505610960 140733505605960 5727998 0 0 16781312 2 0 0 0 17 0 0 0 0 0 0 /proc/14472/statm: 28383 7154 1043 628 0 5966 0 Current children cumulated CPU time (s) 0.11 Current children cumulated vsize (KiB) 113532 [startup+0.200252 s] /proc/loadavg: 0.99 0.98 0.99 2/53 14472 /proc/meminfo: memFree=389332/1022884 swapFree=0/0 [pid=14472] ppid=14471 vsize=122620 CPUtime=0.19 /proc/14472/stat : 14472 (smart) R 14471 14472 2806 34818 2806 4202496 12101 414 0 0 16 3 0 0 20 0 1 0 7785108 125562880 8360 18446744073709551615 4194304 6763684 140733505610960 140733505606936 139792030013712 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/14472/statm: 30655 8360 1058 628 0 7208 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 122620 [startup+0.30024 s] /proc/loadavg: 0.99 0.98 0.99 2/53 14472 /proc/meminfo: memFree=389332/1022884 swapFree=0/0 [pid=14472] ppid=14471 vsize=139308 CPUtime=0.29 /proc/14472/stat : 14472 (smart) R 14471 14472 2806 34818 2806 4202496 18836 414 0 0 23 6 0 0 20 0 1 0 7785108 142651392 12585 18446744073709551615 4194304 6763684 140733505610960 140733505606936 5763274 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/14472/statm: 34827 12585 1059 628 0 11380 0 Current children cumulated CPU time (s) 0.29 Current children cumulated vsize (KiB) 139308 [startup+0.700183 s] /proc/loadavg: 0.99 0.98 0.99 2/53 14472 /proc/meminfo: memFree=389332/1022884 swapFree=0/0 [pid=14472] ppid=14471 vsize=200392 CPUtime=0.69 /proc/14472/stat : 14472 (smart) R 14471 14472 2806 34818 2806 4202496 37682 414 0 0 58 11 0 0 20 0 1 0 7785108 205201408 27855 18446744073709551615 4194304 6763684 140733505610960 140733505606936 139792048169981 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/14472/statm: 50098 27855 1059 628 0 26651 0 Current children cumulated CPU time (s) 0.69 Current children cumulated vsize (KiB) 200392 [startup+1.5002 s] /proc/loadavg: 0.99 0.98 0.99 2/54 14475 /proc/meminfo: memFree=245360/1022884 swapFree=0/0 [pid=14472] ppid=14471 vsize=236416 CPUtime=1.49 /proc/14472/stat : 14472 (smart) R 14471 14472 2806 34818 2806 4202496 52871 414 0 0 134 15 0 0 20 0 1 0 7785108 242089984 36864 18446744073709551615 4194304 6763684 140733505610960 140733505607488 5743568 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/14472/statm: 59104 36864 1068 628 0 35657 0 Current children cumulated CPU time (s) 1.49 Current children cumulated vsize (KiB) 236416 [startup+3.10019 s] /proc/loadavg: 0.99 0.98 0.99 2/54 14475 /proc/meminfo: memFree=206052/1022884 swapFree=0/0 [pid=14472] ppid=14471 vsize=276004 CPUtime=3.07 /proc/14472/stat : 14472 (smart) R 14471 14472 2806 34818 2806 4202496 62781 414 0 0 291 16 0 0 20 0 1 0 7785108 282628096 46763 18446744073709551615 4194304 6763684 140733505610960 140733505607912 139792029928760 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/14472/statm: 69001 46763 1070 628 0 45554 0 Current children cumulated CPU time (s) 3.07 Current children cumulated vsize (KiB) 276004 [startup+6.30019 s] /proc/loadavg: 0.99 0.98 0.99 2/54 14475 /proc/meminfo: memFree=206052/1022884 swapFree=0/0 [pid=14472] ppid=14471 vsize=276004 CPUtime=6.26 /proc/14472/stat : 14472 (smart) R 14471 14472 2806 34818 2806 4202496 62784 414 0 0 610 16 0 0 20 0 1 0 7785108 282628096 46766 18446744073709551615 4194304 6763684 140733505610960 140733505607912 139792029925082 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/14472/statm: 69001 46766 1073 628 0 45554 0 Current children cumulated CPU time (s) 6.26 Current children cumulated vsize (KiB) 276004 [startup+12.7002 s] /proc/loadavg: 0.99 0.98 0.99 2/54 14475 /proc/meminfo: memFree=205928/1022884 swapFree=0/0 [pid=14472] ppid=14471 vsize=276004 CPUtime=12.64 /proc/14472/stat : 14472 (smart) R 14471 14472 2806 34818 2806 4202496 62784 414 0 0 1248 16 0 0 20 0 1 0 7785108 282628096 46766 18446744073709551615 4194304 6763684 140733505610960 140733505607912 139792012177089 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/14472/statm: 69001 46766 1073 628 0 45554 0 Current children cumulated CPU time (s) 12.64 Current children cumulated vsize (KiB) 276004 [startup+25.5002 s] /proc/loadavg: 1.07 1.00 1.00 3/54 14620 /proc/meminfo: memFree=205424/1022884 swapFree=0/0 [pid=14472] ppid=14471 vsize=276004 CPUtime=23.52 /proc/14472/stat : 14472 (smart) R 14471 14472 2806 34818 2806 4202496 62784 414 0 0 2335 17 0 0 20 0 1 0 7785108 282628096 46766 18446744073709551615 4194304 6763684 140733505610960 140733505607912 139792029925216 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/14472/statm: 69001 46766 1073 628 0 45554 0 Current children cumulated CPU time (s) 23.52 Current children cumulated vsize (KiB) 276004 [startup+51.1002 s] /proc/loadavg: 1.10 1.01 1.00 2/54 14704 /proc/meminfo: memFree=205052/1022884 swapFree=0/0 [pid=14472] ppid=14471 vsize=276004 CPUtime=48.03 /proc/14472/stat : 14472 (smart) R 14471 14472 2806 34818 2806 4202496 62784 414 0 0 4786 17 0 0 20 0 1 0 7785108 282628096 46766 18446744073709551615 4194304 6763684 140733505610960 140733505607912 139792029925082 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/14472/statm: 69001 46766 1073 628 0 45554 0 Current children cumulated CPU time (s) 48.03 Current children cumulated vsize (KiB) 276004 [startup+102.3 s] /proc/loadavg: 1.04 1.01 1.00 2/54 14704 /proc/meminfo: memFree=204928/1022884 swapFree=0/0 [pid=14472] ppid=14471 vsize=276004 CPUtime=99.04 /proc/14472/stat : 14472 (smart) R 14471 14472 2806 34818 2806 4202496 62786 414 0 0 9887 17 0 0 20 0 1 0 7785108 282628096 46766 18446744073709551615 4194304 6763684 140733505610960 140733505607912 139792012177089 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/14472/statm: 69001 46766 1073 628 0 45554 0 Current children cumulated CPU time (s) 99.04 Current children cumulated vsize (KiB) 276004 [startup+162.3 s] /proc/loadavg: 1.01 1.00 1.00 2/54 14704 /proc/meminfo: memFree=204928/1022884 swapFree=0/0 [pid=14472] ppid=14471 vsize=276004 CPUtime=158.82 /proc/14472/stat : 14472 (smart) R 14471 14472 2806 34818 2806 4202496 62786 414 0 0 15865 17 0 0 20 0 1 0 7785108 282628096 46766 18446744073709551615 4194304 6763684 140733505610960 140733505607912 139792029928752 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/14472/statm: 69001 46766 1073 628 0 45554 0 Current children cumulated CPU time (s) 158.82 Current children cumulated vsize (KiB) 276004 [startup+222.303 s] /proc/loadavg: 1.00 1.00 1.00 2/54 14704 /proc/meminfo: memFree=204928/1022884 swapFree=0/0 [pid=14472] ppid=14471 vsize=276004 CPUtime=218.6 /proc/14472/stat : 14472 (smart) R 14471 14472 2806 34818 2806 4202496 62786 414 0 0 21843 17 0 0 20 0 1 0 7785108 282628096 46766 18446744073709551615 4194304 6763684 140733505610960 140733505607912 139792029925082 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/14472/statm: 69001 46766 1073 628 0 45554 0 Current children cumulated CPU time (s) 218.6 Current children cumulated vsize (KiB) 276004 [startup+282.3 s] /proc/loadavg: 1.00 1.00 1.00 2/54 14712 /proc/meminfo: memFree=204928/1022884 swapFree=0/0 [pid=14472] ppid=14471 vsize=276004 CPUtime=278.36 /proc/14472/stat : 14472 (smart) R 14471 14472 2806 34818 2806 4202496 62787 414 0 0 27819 17 0 0 20 0 1 0 7785108 282628096 46766 18446744073709551615 4194304 6763684 140733505610960 140733505607912 139792012177089 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/14472/statm: 69001 46766 1073 628 0 45554 0 Current children cumulated CPU time (s) 278.36 Current children cumulated vsize (KiB) 276004 Maximum wall clock time exceeded: sending signal-name then SIGKILL [startup+300 s] /proc/loadavg: 1.00 1.00 1.00 2/54 14712 /proc/meminfo: memFree=204928/1022884 swapFree=0/0 [pid=14472] ppid=14471 vsize=276004 CPUtime=296 /proc/14472/stat : 14472 (smart) R 14471 14472 2806 34818 2806 4202496 62787 414 0 0 29583 17 0 0 20 0 1 0 7785108 282628096 46766 18446744073709551615 4194304 6763684 140733505610960 140733505607912 139792029928760 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/14472/statm: 69001 46766 1073 628 0 45554 0 Current children cumulated CPU time (s) 296 Current children cumulated vsize (KiB) 276004 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 14712 /proc/meminfo: memFree=204928/1022884 swapFree=0/0 [pid=14472] ppid=14471 vsize=276004 CPUtime=296 /proc/14472/stat : 14472 (smart) R 14471 14472 2806 34818 2806 4202496 62787 414 0 0 29583 17 0 0 20 0 1 0 7785108 282628096 46766 18446744073709551615 4194304 6763684 140733505610960 140733505607912 139792029928760 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/14472/statm: 69001 46766 1073 628 0 45554 0 Current children cumulated CPU time (s) 296 Current children cumulated vsize (KiB) 276004 Child ended because it received signal 15 (SIGTERM) Real time (s): 300.024 CPU time (s): 296.026 CPU user time (s): 295.834 CPU system time (s): 0.192012 CPU usage (%): 98.6676 Max. virtual memory (cumulated for all children) (KiB): 276004 getrusage(RUSAGE_CHILDREN,...) data: user time used= 295.834 system time used= 0.192012 maximum resident set size= 187064 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 63201 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= 5447 runsolver used 0.440027 second user time and 0.828051 second system time The end