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/62.runsolver.aptitude aptitude -s -y --without-recommends install kernel-image-2.4.27-speakup drupal jftpgw libvibrant6 records-common 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.00 1.03 1.03 2/55 25770 /proc/meminfo: memFree=829444/1022884 swapFree=0/0 [pid=25770] ppid=25769 vsize=3152 CPUtime=0 /proc/25770/stat : 25770 (runsolver) R 25769 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29616042 3227648 33 18446744073709551615 134512640 134586868 4290906240 4290904288 4151489584 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/25770/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.111821 s] /proc/loadavg: 1.00 1.03 1.03 2/55 25770 /proc/meminfo: memFree=829444/1022884 swapFree=0/0 [pid=25770] ppid=25769 vsize=103288 CPUtime=0.09 /proc/25770/stat : 25770 (aptitude) R 25769 25770 17863 34816 17863 4202496 11194 1708 0 0 7 2 0 0 20 0 1 0 29616042 105766912 10995 18446744073709551615 139686006611968 139686010919320 140734519758224 140734519749488 139686001453289 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25770/statm: 25822 10995 9783 1052 0 1159 0 Current children cumulated CPU time (s) 0.09 Current children cumulated vsize (KiB) 103288 [startup+0.200326 s] /proc/loadavg: 1.00 1.03 1.03 2/55 25770 /proc/meminfo: memFree=829444/1022884 swapFree=0/0 [pid=25770] ppid=25769 vsize=103288 CPUtime=0.18 /proc/25770/stat : 25770 (aptitude) R 25769 25770 17863 34816 17863 4202496 11302 1708 0 0 16 2 0 0 20 0 1 0 29616042 105766912 11103 18446744073709551615 139686006611968 139686010919320 140734519758224 140734519749488 139686001455320 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25770/statm: 25822 11103 9891 1052 0 1159 0 Current children cumulated CPU time (s) 0.18 Current children cumulated vsize (KiB) 103288 [startup+0.300254 s] /proc/loadavg: 1.00 1.03 1.03 2/55 25770 /proc/meminfo: memFree=829444/1022884 swapFree=0/0 [pid=25770] ppid=25769 vsize=114256 CPUtime=0.28 /proc/25770/stat : 25770 (aptitude) R 25769 25770 17863 34816 17863 4202496 14138 1708 0 0 25 3 0 0 20 0 1 0 29616042 116998144 13931 18446744073709551615 139686006611968 139686010919320 140734519758224 140734519749872 139685975353342 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25770/statm: 28564 13931 9961 1052 0 3901 0 Current children cumulated CPU time (s) 0.28 Current children cumulated vsize (KiB) 114256 [startup+0.700187 s] /proc/loadavg: 1.00 1.03 1.03 2/55 25770 /proc/meminfo: memFree=829444/1022884 swapFree=0/0 [pid=25770] ppid=25769 vsize=123068 CPUtime=0.68 /proc/25770/stat : 25770 (aptitude) R 25769 25770 17863 34816 17863 4202496 17688 1708 0 0 63 5 0 0 20 0 1 0 29616042 126021632 15965 18446744073709551615 139686006611968 139686010919320 140734519758224 140734519747656 139686001512609 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25770/statm: 30767 15965 9976 1052 0 6104 0 Current children cumulated CPU time (s) 0.68 Current children cumulated vsize (KiB) 123068 [startup+1.50026 s] /proc/loadavg: 1.00 1.03 1.03 2/57 25775 /proc/meminfo: memFree=809472/1022884 swapFree=0/0 [pid=25770] ppid=25769 vsize=136076 CPUtime=1.48 /proc/25770/stat : 25770 (aptitude) R 25769 25770 17863 34816 17863 4202496 20675 1708 0 0 142 6 0 0 20 0 2 0 29616042 139341824 17592 18446744073709551615 139686006611968 139686010919320 140734519758224 140734519749496 139686001435882 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25770/statm: 34019 17592 10213 1052 0 9356 0 [pid=25770/tid=25775] ppid=25769 vsize=136076 CPUtime=0 /proc/25770/task/25775/stat : 25775 (aptitude) S 25769 25770 17863 34816 17863 4202560 4 1708 0 0 0 0 0 0 20 0 2 0 29616113 139341824 17592 18446744073709551615 139686006611968 139686010919320 140734519758224 139685894289408 139685975356116 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 1.48 Current children cumulated vsize (KiB) 136076 [startup+3.10023 s] /proc/loadavg: 1.00 1.03 1.03 2/57 25775 /proc/meminfo: memFree=799180/1022884 swapFree=0/0 [pid=25770] ppid=25769 vsize=137840 CPUtime=3.06 /proc/25770/stat : 25770 (aptitude) R 25769 25770 17863 34816 17863 4202496 22028 2211 0 0 296 10 0 0 20 0 2 0 29616042 141148160 17939 18446744073709551615 139686006611968 139686010919320 140734519758224 140734519744928 139685975352878 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25770/statm: 34460 17939 10303 1052 0 9797 0 [pid=25770/tid=25775] ppid=25769 vsize=137840 CPUtime=0 /proc/25770/task/25775/stat : 25775 (aptitude) S 25769 25770 17863 34816 17863 4202560 6 2211 0 0 0 0 0 0 20 0 2 0 29616113 141148160 17939 18446744073709551615 139686006611968 139686010919320 140734519758224 139685894289408 139685975356116 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 3.06 Current children cumulated vsize (KiB) 137840 [startup+6.30023 s] /proc/loadavg: 1.00 1.03 1.03 2/57 25776 /proc/meminfo: memFree=756648/1022884 swapFree=0/0 [pid=25770] ppid=25769 vsize=251836 CPUtime=6.26 /proc/25770/stat : 25770 (aptitude) S 25769 25770 17863 34816 17863 4202496 34898 2211 0 0 610 16 0 0 20 0 2 0 29616042 257880064 30289 18446744073709551615 139686006611968 139686010919320 140734519758224 140734519749984 139685975357003 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25770/statm: 62959 30289 10359 1052 0 38296 0 [pid=25770/tid=25775] ppid=25769 vsize=251836 CPUtime=2.91 /proc/25770/task/25775/stat : 25775 (aptitude) R 25769 25770 17863 34816 17863 4202560 12869 2211 0 0 286 5 0 0 20 0 2 0 29616113 257880064 30289 18446744073709551615 139686006611968 139686010919320 140734519758224 139685894280728 139686009413935 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 6.26 Current children cumulated vsize (KiB) 251836 [startup+12.7002 s] /proc/loadavg: 1.00 1.03 1.03 2/57 25776 /proc/meminfo: memFree=707420/1022884 swapFree=0/0 [pid=25770] ppid=25769 vsize=296796 CPUtime=12.63 /proc/25770/stat : 25770 (aptitude) S 25769 25770 17863 34816 17863 4202496 46325 2211 0 0 1242 21 0 0 20 0 2 0 29616042 303919104 41518 18446744073709551615 139686006611968 139686010919320 140734519758224 140734519749984 139685975357003 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25770/statm: 74199 41518 10360 1052 0 49536 0 [pid=25770/tid=25775] ppid=25769 vsize=296796 CPUtime=9.28 /proc/25770/task/25775/stat : 25775 (aptitude) R 25769 25770 17863 34816 17863 4202560 24296 2211 0 0 918 10 0 0 20 0 2 0 29616113 303919104 41518 18446744073709551615 139686006611968 139686010919320 140734519758224 139685894283768 139686009222085 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 12.63 Current children cumulated vsize (KiB) 296796 [startup+25.5003 s] /proc/loadavg: 1.00 1.03 1.03 2/57 25776 /proc/meminfo: memFree=629424/1022884 swapFree=0/0 [pid=25770] ppid=25769 vsize=372248 CPUtime=25.34 /proc/25770/stat : 25770 (aptitude) S 25769 25770 17863 34816 17863 4202496 65854 2211 0 0 2501 33 0 0 20 0 2 0 29616042 381181952 60380 18446744073709551615 139686006611968 139686010919320 140734519758224 140734519749984 139685975357003 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25770/statm: 93062 60380 10360 1052 0 68399 0 [pid=25770/tid=25775] ppid=25769 vsize=372248 CPUtime=22 /proc/25770/task/25775/stat : 25775 (aptitude) R 25769 25770 17863 34816 17863 4202560 43825 2211 0 0 2178 22 0 0 20 0 2 0 29616113 381181952 60380 18446744073709551615 139686006611968 139686010919320 140734519758224 139685894280728 139686009282102 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0 Current children cumulated CPU time (s) 25.34 Current children cumulated vsize (KiB) 372248 [startup+51.1003 s] /proc/loadavg: 1.00 1.03 1.02 2/57 25776 /proc/meminfo: memFree=453716/1022884 swapFree=0/0 [pid=25770] ppid=25769 vsize=549280 CPUtime=50.84 /proc/25770/stat : 25770 (aptitude) S 25769 25770 17863 34816 17863 4202496 110246 2211 0 0 5035 49 0 0 20 0 2 0 29616042 562462720 104629 18446744073709551615 139686006611968 139686010919320 140734519758224 140734519749984 139685975357003 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25770/statm: 137320 104629 10360 1052 0 112657 0 [pid=25770/tid=25775] ppid=25769 vsize=549280 CPUtime=47.49 /proc/25770/task/25775/stat : 25775 (aptitude) R 25769 25770 17863 34816 17863 4202560 88217 2211 0 0 4711 38 0 0 20 0 2 0 29616113 562462720 104629 18446744073709551615 139686006611968 139686010919320 140734519758224 139685894283064 139686009238510 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0 Current children cumulated CPU time (s) 50.84 Current children cumulated vsize (KiB) 549280 [startup+102.3 s] /proc/loadavg: 1.26 1.08 1.04 2/57 25776 /proc/meminfo: memFree=8280/1022884 swapFree=0/0 [pid=25770] ppid=25769 vsize=1075220 CPUtime=98.49 /proc/25770/stat : 25770 (aptitude) S 25769 25770 17863 34816 17863 4202496 242219 2211 435 0 9728 121 0 0 20 0 2 0 29616042 1101025280 231135 18446744073709551615 139686006611968 139686010919320 140734519758224 140734519749984 139685975357003 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25770/statm: 268805 231135 9130 1052 0 244142 0 [pid=25770/tid=25775] ppid=25769 vsize=1075220 CPUtime=95.14 /proc/25770/task/25775/stat : 25775 (aptitude) R 25769 25770 17863 34816 17863 4202560 220171 2211 431 0 9404 110 0 0 20 0 2 0 29616113 1101025280 231135 18446744073709551615 139686006611968 139686010919320 140734519758224 139685894280776 139686009282067 0 134217728 4096 0 0 0 0 -1 0 0 0 316 0 0 Current children cumulated CPU time (s) 98.49 Current children cumulated vsize (KiB) 1075220 Maximum VSize exceeded: sending signal-name then SIGKILL [startup+110.9 s] /proc/loadavg: 1.40 1.11 1.05 2/57 25776 /proc/meminfo: memFree=8664/1022884 swapFree=0/0 [pid=25770] ppid=25769 vsize=1151648 CPUtime=105.82 /proc/25770/stat : 25770 (aptitude) S 25769 25770 17863 34816 17863 4202496 261475 2211 573 0 10448 134 0 0 20 0 2 0 29616042 1179287552 246508 18446744073709551615 139686006611968 139686010919320 140734519758224 140734519749984 139685975357003 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25770/statm: 287912 246508 9375 1052 0 263249 0 [pid=25770/tid=25775] ppid=25769 vsize=1151648 CPUtime=102.46 /proc/25770/task/25775/stat : 25775 (aptitude) R 25769 25770 17863 34816 17863 4202560 239427 2211 569 0 10123 123 0 0 20 0 2 0 29616113 1179287552 246508 18446744073709551615 139686006611968 139686010919320 140734519758224 139685894281080 139686009438769 0 134217728 4096 0 0 0 0 -1 0 0 0 433 0 0 Current children cumulated CPU time (s) 105.82 Current children cumulated vsize (KiB) 1151648 Sending Terminated to process tree (bottom up) Sleeping 2 seconds Solver just ended. Dumping a history of the last processes samples Child ended because it received signal 15 (SIGTERM) Real time (s): 111.055 CPU time (s): 105.979 CPU user time (s): 104.563 CPU system time (s): 1.41609 CPU usage (%): 95.429 Max. virtual memory (cumulated for all children) (KiB): 1151648 getrusage(RUSAGE_CHILDREN,...) data: user time used= 104.563 system time used= 1.41609 maximum resident set size= 986764 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 263869 page faults= 573 swaps= 0 block input operations= 21640 block output operations= 80 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 902 involuntary context switches= 2366 runsolver used 0.128008 second user time and 0.380023 second system time The end