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/7.runsolver.aptitude aptitude -s -y --without-recommends install libxml-filter-xslt-perl libio-socket-inet6-perl apache2-mpm-threadpool hotplug libgpewidget-dev 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.04 1.03 1.00 2/55 22732 /proc/meminfo: memFree=868956/1022884 swapFree=0/0 [pid=22732] ppid=22731 vsize=3152 CPUtime=0 /proc/22732/stat : 22732 (runsolver) R 22731 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28748453 3227648 32 18446744073709551615 134512640 134586868 4294905264 4294903312 4152218672 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/22732/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.190753 s] /proc/loadavg: 1.04 1.03 1.00 2/55 22732 /proc/meminfo: memFree=868956/1022884 swapFree=0/0 [pid=22732] ppid=22731 vsize=100508 CPUtime=0.17 /proc/22732/stat : 22732 (aptitude) R 22731 22732 17863 34816 17863 4202496 10604 1709 0 0 16 1 0 0 20 0 1 0 28748453 102920192 10405 18446744073709551615 139677607161856 139677611469208 140734818260928 140734818252192 139677602562181 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/22732/statm: 25127 10405 9231 1052 0 1122 0 Current children cumulated CPU time (s) 0.17 Current children cumulated vsize (KiB) 100508 [startup+0.200283 s] /proc/loadavg: 1.04 1.03 1.00 2/55 22732 /proc/meminfo: memFree=868956/1022884 swapFree=0/0 [pid=22732] ppid=22731 vsize=100508 CPUtime=0.18 /proc/22732/stat : 22732 (aptitude) R 22731 22732 17863 34816 17863 4202496 10605 1709 0 0 17 1 0 0 20 0 1 0 28748453 102920192 10406 18446744073709551615 139677607161856 139677611469208 140734818260928 140734818252192 139677607990884 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/22732/statm: 25127 10406 9232 1052 0 1122 0 Current children cumulated CPU time (s) 0.18 Current children cumulated vsize (KiB) 100508 [startup+0.300266 s] /proc/loadavg: 1.04 1.03 1.00 2/55 22732 /proc/meminfo: memFree=868956/1022884 swapFree=0/0 [pid=22732] ppid=22731 vsize=111108 CPUtime=0.28 /proc/22732/stat : 22732 (aptitude) R 22731 22732 17863 34816 17863 4202496 12635 1709 0 0 27 1 0 0 20 0 1 0 28748453 113774592 12428 18446744073709551615 139677607161856 139677611469208 140734818260928 140734818252520 139677609293403 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/22732/statm: 27777 12428 9302 1052 0 3772 0 Current children cumulated CPU time (s) 0.28 Current children cumulated vsize (KiB) 111108 [startup+0.700199 s] /proc/loadavg: 1.04 1.03 1.00 2/55 22732 /proc/meminfo: memFree=868956/1022884 swapFree=0/0 [pid=22732] ppid=22731 vsize=123288 CPUtime=0.68 /proc/22732/stat : 22732 (aptitude) R 22731 22732 17863 34816 17863 4202496 17027 1709 0 0 64 4 0 0 20 0 2 0 28748453 126246912 14302 18446744073709551615 139677607161856 139677611469208 140734818260928 140734818256712 139677602005369 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22732/statm: 30822 14302 9482 1052 0 6817 0 Current children cumulated CPU time (s) 0.68 Current children cumulated vsize (KiB) 123288 [startup+1.50024 s] /proc/loadavg: 1.04 1.03 1.00 2/57 22737 /proc/meminfo: memFree=840676/1022884 swapFree=0/0 [pid=22732] ppid=22731 vsize=132404 CPUtime=1.48 /proc/22732/stat : 22732 (aptitude) R 22731 22732 17863 34816 17863 4202496 19436 1709 0 0 143 5 0 0 20 0 2 0 28748453 135581696 16707 18446744073709551615 139677607161856 139677611469208 140734818260928 140734818251280 139677610155046 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22732/statm: 33101 16707 9585 1052 0 9096 0 [pid=22732/tid=22737] ppid=22731 vsize=132404 CPUtime=0 /proc/22732/task/22737/stat : 22737 (aptitude) S 22731 22732 17863 34816 17863 4202560 4 1709 0 0 0 0 0 0 20 0 2 0 28748519 135581696 16707 18446744073709551615 139677607161856 139677611469208 140734818260928 139677497989120 139677575906004 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) 132404 [startup+3.10025 s] /proc/loadavg: 1.04 1.03 1.00 2/57 22738 /proc/meminfo: memFree=839428/1022884 swapFree=0/0 [pid=22732] ppid=22731 vsize=133908 CPUtime=3.07 /proc/22732/stat : 22732 (aptitude) R 22731 22732 17863 34816 17863 4202496 20613 2208 0 0 299 8 0 0 20 0 2 0 28748453 137121792 16943 18446744073709551615 139677607161856 139677611469208 140734818260928 140734818247744 139677601989676 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22732/statm: 33477 16943 9644 1052 0 9472 0 [pid=22732/tid=22737] ppid=22731 vsize=133908 CPUtime=0 /proc/22732/task/22737/stat : 22737 (aptitude) S 22731 22732 17863 34816 17863 4202560 6 2208 0 0 0 0 0 0 20 0 2 0 28748519 137121792 16943 18446744073709551615 139677607161856 139677611469208 140734818260928 139677497989120 139677575906004 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 3.07 Current children cumulated vsize (KiB) 133908 [startup+6.30025 s] /proc/loadavg: 1.04 1.03 1.00 2/57 22738 /proc/meminfo: memFree=797772/1022884 swapFree=0/0 [pid=22732] ppid=22731 vsize=246704 CPUtime=6.26 /proc/22732/stat : 22732 (aptitude) S 22731 22732 17863 34816 17863 4202496 33601 2208 0 0 612 14 0 0 20 0 2 0 28748453 252624896 28998 18446744073709551615 139677607161856 139677611469208 140734818260928 140734818252688 139677575906891 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22732/statm: 61676 28998 9700 1052 0 37671 0 [pid=22732/tid=22737] ppid=22731 vsize=246704 CPUtime=3.14 /proc/22732/task/22737/stat : 22737 (aptitude) R 22731 22732 17863 34816 17863 4202560 12987 2208 0 0 308 6 0 0 20 0 2 0 28748519 252624896 28998 18446744073709551615 139677607161856 139677611469208 140734818260928 139677497980440 139677609786403 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) 246704 [startup+12.7003 s] /proc/loadavg: 1.03 1.03 1.00 2/57 22738 /proc/meminfo: memFree=741352/1022884 swapFree=0/0 [pid=22732] ppid=22731 vsize=300944 CPUtime=12.62 /proc/22732/stat : 22732 (aptitude) S 22731 22732 17863 34816 17863 4202496 47305 2208 0 0 1244 18 0 0 20 0 2 0 28748453 308166656 42575 18446744073709551615 139677607161856 139677611469208 140734818260928 140734818252688 139677575906891 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22732/statm: 75236 42575 9700 1052 0 51231 0 [pid=22732/tid=22737] ppid=22731 vsize=300944 CPUtime=9.51 /proc/22732/task/22737/stat : 22737 (aptitude) R 22731 22732 17863 34816 17863 4202560 26691 2208 0 0 941 10 0 0 20 0 2 0 28748519 308166656 42575 18446744073709551615 139677607161856 139677611469208 140734818260928 139677497980440 139677564672427 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 12.62 Current children cumulated vsize (KiB) 300944 [startup+25.5003 s] /proc/loadavg: 1.03 1.03 1.00 2/57 22738 /proc/meminfo: memFree=643144/1022884 swapFree=0/0 [pid=22732] ppid=22731 vsize=395700 CPUtime=25.36 /proc/22732/stat : 22732 (aptitude) S 22731 22732 17863 34816 17863 4202496 71254 2208 0 0 2510 26 0 0 20 0 2 0 28748453 405196800 66209 18446744073709551615 139677607161856 139677611469208 140734818260928 140734818252688 139677575906891 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22732/statm: 98925 66209 9700 1052 0 74920 0 [pid=22732/tid=22737] ppid=22731 vsize=395700 CPUtime=22.24 /proc/22732/task/22737/stat : 22737 (aptitude) R 22731 22732 17863 34816 17863 4202560 50640 2208 0 0 2206 18 0 0 20 0 2 0 28748519 405196800 66209 18446744073709551615 139677607161856 139677611469208 140734818260928 139677497980440 139677609746686 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 25.36 Current children cumulated vsize (KiB) 395700 [startup+51.1003 s] /proc/loadavg: 1.02 1.02 1.00 2/57 22738 /proc/meminfo: memFree=440776/1022884 swapFree=0/0 [pid=22732] ppid=22731 vsize=601160 CPUtime=50.84 /proc/22732/stat : 22732 (aptitude) S 22731 22732 17863 34816 17863 4202496 122685 2208 0 0 5032 52 0 0 20 0 2 0 28748453 615587840 117549 18446744073709551615 139677607161856 139677611469208 140734818260928 140734818252688 139677575906891 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22732/statm: 150290 117549 9715 1052 0 126285 0 [pid=22732/tid=22737] ppid=22731 vsize=601160 CPUtime=47.73 /proc/22732/task/22737/stat : 22737 (aptitude) R 22731 22732 17863 34816 17863 4202560 102064 2208 0 0 4729 44 0 0 20 0 2 0 28748519 615587840 117549 18446744073709551615 139677607161856 139677611469208 140734818260928 139677497982648 139677607929221 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 50.84 Current children cumulated vsize (KiB) 601160 [startup+102.3 s] /proc/loadavg: 1.40 1.11 1.03 3/57 22962 /proc/meminfo: memFree=8760/1022884 swapFree=0/0 [pid=22732] ppid=22731 vsize=1041072 CPUtime=95.22 /proc/22732/stat : 22732 (aptitude) S 22731 22732 17863 34816 17863 4202496 232911 2208 145 0 9397 125 0 0 20 0 2 0 28748453 1066057728 226651 18446744073709551615 139677607161856 139677611469208 140734818260928 140734818252688 139677575906891 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22732/statm: 260268 226651 9343 1052 0 236263 0 [pid=22732/tid=22737] ppid=22731 vsize=1041072 CPUtime=92.1 /proc/22732/task/22737/stat : 22737 (aptitude) D 22731 22732 17863 34816 17863 4204608 212290 2208 145 0 9093 117 0 0 20 0 2 0 28748519 1066057728 226651 18446744073709551615 139677607161856 139677611469208 140734818260928 139677497980440 139677564665396 0 134217728 4096 0 0 0 0 -1 0 0 0 356 0 0 Current children cumulated CPU time (s) 95.22 Current children cumulated vsize (KiB) 1041072 Maximum VSize exceeded: sending signal-name then SIGKILL [startup+118.4 s] /proc/loadavg: 1.46 1.14 1.04 2/57 22962 /proc/meminfo: memFree=9768/1022884 swapFree=0/0 [pid=22732] ppid=22731 vsize=1151556 CPUtime=106.97 /proc/22732/stat : 22732 (aptitude) S 22731 22732 17863 34816 17863 4202496 260797 2208 476 0 10552 145 0 0 20 0 2 0 28748453 1179193344 232350 18446744073709551615 139677607161856 139677611469208 140734818260928 140734818252688 139677575906891 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 5 0 0 /proc/22732/statm: 287889 232350 8141 1052 0 263884 0 [pid=22732/tid=22737] ppid=22731 vsize=1151556 CPUtime=103.85 /proc/22732/task/22737/stat : 22737 (aptitude) R 22731 22732 17863 34816 17863 4202560 240155 2208 468 0 10248 137 0 0 20 0 2 0 28748519 1179193344 232350 18446744073709551615 139677607161856 139677611469208 140734818260928 139677497982552 139677564672136 0 134217728 4096 0 0 0 0 -1 0 0 0 732 0 0 Current children cumulated CPU time (s) 106.97 Current children cumulated vsize (KiB) 1151556 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): 118.579 CPU time (s): 107.139 CPU user time (s): 105.615 CPU system time (s): 1.52409 CPU usage (%): 90.3521 Max. virtual memory (cumulated for all children) (KiB): 1151556 getrusage(RUSAGE_CHILDREN,...) data: user time used= 105.615 system time used= 1.52409 maximum resident set size= 934524 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 263182 page faults= 477 swaps= 0 block input operations= 25208 block output operations= 88 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 840 involuntary context switches= 7088 runsolver used 0.16801 second user time and 0.388024 second system time The end