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/96.runsolver.aptitude aptitude -s -y --without-recommends install koffice-i18n-fi gforge-db-postgresql libdshconfig1-dev misdn-kernel-headers yarssr 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.02 1.03 1.00 2/55 22160 /proc/meminfo: memFree=911832/1022884 swapFree=0/0 [pid=22160] ppid=22159 vsize=3152 CPUtime=0 /proc/22160/stat : 22160 (runsolver) R 22159 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28637434 3227648 32 18446744073709551615 134512640 134586868 4294798608 4294796656 4152161328 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/22160/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.160088 s] /proc/loadavg: 1.02 1.03 1.00 2/55 22160 /proc/meminfo: memFree=911832/1022884 swapFree=0/0 [pid=22160] ppid=22159 vsize=89152 CPUtime=0.15 /proc/22160/stat : 22160 (aptitude) R 22159 22160 17863 34816 17863 4202496 7775 1708 0 0 13 2 0 0 20 0 1 0 28637434 91291648 7573 18446744073709551615 140170587095040 140170591402392 140733312447872 140733312439136 140170582494781 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/22160/statm: 22288 7573 6663 1052 0 858 0 Current children cumulated CPU time (s) 0.15 Current children cumulated vsize (KiB) 89152 [startup+0.200363 s] /proc/loadavg: 1.02 1.03 1.00 2/55 22160 /proc/meminfo: memFree=911832/1022884 swapFree=0/0 [pid=22160] ppid=22159 vsize=89152 CPUtime=0.19 /proc/22160/stat : 22160 (aptitude) R 22159 22160 17863 34816 17863 4202496 7871 1708 0 0 17 2 0 0 20 0 1 0 28637434 91291648 7661 18446744073709551615 140170587095040 140170591402392 140733312447872 140733312437648 140170581911668 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/22160/statm: 22288 7661 6726 1052 0 858 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 89152 [startup+0.300276 s] /proc/loadavg: 1.02 1.03 1.00 2/55 22160 /proc/meminfo: memFree=911832/1022884 swapFree=0/0 [pid=22160] ppid=22159 vsize=100164 CPUtime=0.28 /proc/22160/stat : 22160 (aptitude) R 22159 22160 17863 34816 17863 4202496 11281 1708 0 0 25 3 0 0 20 0 1 0 28637434 102567936 10326 18446744073709551615 140170587095040 140170591402392 140733312447872 140733312437384 140170590034095 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/22160/statm: 25041 10326 6742 1052 0 3611 0 Current children cumulated CPU time (s) 0.28 Current children cumulated vsize (KiB) 100164 [startup+0.700266 s] /proc/loadavg: 1.02 1.03 1.00 2/55 22160 /proc/meminfo: memFree=911832/1022884 swapFree=0/0 [pid=22160] ppid=22159 vsize=110256 CPUtime=0.69 /proc/22160/stat : 22160 (aptitude) R 22159 22160 17863 34816 17863 4202496 12730 1708 0 0 64 5 0 0 20 0 2 0 28637434 112902144 11101 18446744073709551615 140170587095040 140170591402392 140733312447872 140733312439912 140170589305930 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22160/statm: 27564 11101 6966 1052 0 6134 0 Current children cumulated CPU time (s) 0.69 Current children cumulated vsize (KiB) 110256 [startup+1.50024 s] /proc/loadavg: 1.02 1.03 1.00 2/57 22165 /proc/meminfo: memFree=890992/1022884 swapFree=0/0 [pid=22160] ppid=22159 vsize=115440 CPUtime=1.48 /proc/22160/stat : 22160 (aptitude) R 22159 22160 17863 34816 17863 4202496 14580 2206 0 0 140 8 0 0 20 0 2 0 28637434 118210560 12373 18446744073709551615 140170587095040 140170591402392 140733312447872 140733312439896 140170589344839 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22160/statm: 28860 12373 7073 1052 0 7430 0 [pid=22160/tid=22165] ppid=22159 vsize=115440 CPUtime=0 /proc/22160/task/22165/stat : 22165 (aptitude) S 22159 22160 17863 34816 17863 4202560 6 2206 0 0 0 0 0 0 20 0 2 0 28637480 118210560 12373 18446744073709551615 140170587095040 140170591402392 140733312447872 140170490501120 140170555839188 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) 115440 [startup+3.10024 s] /proc/loadavg: 1.02 1.03 1.00 2/57 22166 /proc/meminfo: memFree=884048/1022884 swapFree=0/0 [pid=22160] ppid=22159 vsize=136704 CPUtime=3.07 /proc/22160/stat : 22160 (aptitude) S 22159 22160 17863 34816 17863 4202496 20860 2206 0 0 295 12 0 0 20 0 2 0 28637434 139984896 17881 18446744073709551615 140170587095040 140170591402392 140733312447872 140733312439632 140170555840075 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22160/statm: 34176 17881 7129 1052 0 12746 0 [pid=22160/tid=22165] ppid=22159 vsize=136704 CPUtime=1.04 /proc/22160/task/22165/stat : 22165 (aptitude) R 22159 22160 17863 34816 17863 4202560 6205 2206 0 0 100 4 0 0 20 0 2 0 28637480 139984896 17881 18446744073709551615 140170587095040 140170591402392 140733312447872 140170490496616 140170589305946 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) 136704 [startup+6.3003 s] /proc/loadavg: 1.02 1.03 1.00 2/57 22166 /proc/meminfo: memFree=837176/1022884 swapFree=0/0 [pid=22160] ppid=22159 vsize=244908 CPUtime=6.25 /proc/22160/stat : 22160 (aptitude) S 22159 22160 17863 34816 17863 4202496 31539 2206 0 0 606 19 0 0 20 0 2 0 28637434 250785792 28553 18446744073709551615 140170587095040 140170591402392 140733312447872 140733312439632 140170555840075 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22160/statm: 61227 28553 7129 1052 0 39797 0 [pid=22160/tid=22165] ppid=22159 vsize=244908 CPUtime=4.22 /proc/22160/task/22165/stat : 22165 (aptitude) R 22159 22160 17863 34816 17863 4202560 16883 2206 0 0 411 11 0 0 20 0 2 0 28637480 250785792 28553 18446744073709551615 140170587095040 140170591402392 140733312447872 140170490492616 140170544605320 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 6.25 Current children cumulated vsize (KiB) 244908 [startup+12.7002 s] /proc/loadavg: 1.02 1.03 1.00 2/57 22166 /proc/meminfo: memFree=777036/1022884 swapFree=0/0 [pid=22160] ppid=22159 vsize=297044 CPUtime=12.63 /proc/22160/stat : 22160 (aptitude) S 22159 22160 17863 34816 17863 4202496 44596 2206 0 0 1235 28 0 0 20 0 2 0 28637434 304173056 41579 18446744073709551615 140170587095040 140170591402392 140733312447872 140733312439632 140170555840075 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22160/statm: 74261 41579 7129 1052 0 52831 0 [pid=22160/tid=22165] ppid=22159 vsize=297044 CPUtime=10.6 /proc/22160/task/22165/stat : 22165 (aptitude) R 22159 22160 17863 34816 17863 4202560 29940 2206 0 0 1040 20 0 0 20 0 2 0 28637480 304173056 41579 18446744073709551615 140170587095040 140170591402392 140733312447872 140170490494648 140170589687840 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) 297044 [startup+25.5003 s] /proc/loadavg: 1.01 1.03 1.00 2/57 22166 /proc/meminfo: memFree=710324/1022884 swapFree=0/0 [pid=22160] ppid=22159 vsize=361336 CPUtime=25.37 /proc/22160/stat : 22160 (aptitude) S 22159 22160 17863 34816 17863 4202496 60816 2206 0 0 2499 38 0 0 20 0 2 0 28637434 370008064 57614 18446744073709551615 140170587095040 140170591402392 140733312447872 140733312439632 140170555840075 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22160/statm: 90334 57614 7129 1052 0 68904 0 [pid=22160/tid=22165] ppid=22159 vsize=361336 CPUtime=23.33 /proc/22160/task/22165/stat : 22165 (aptitude) R 22159 22160 17863 34816 17863 4202560 46160 2206 0 0 2303 30 0 0 20 0 2 0 28637480 370008064 57614 18446744073709551615 140170587095040 140170591402392 140733312447872 140170490494648 140170589756553 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 25.37 Current children cumulated vsize (KiB) 361336 [startup+51.1003 s] /proc/loadavg: 1.07 1.04 1.00 2/57 22166 /proc/meminfo: memFree=602196/1022884 swapFree=0/0 [pid=22160] ppid=22159 vsize=471056 CPUtime=50.85 /proc/22160/stat : 22160 (aptitude) S 22159 22160 17863 34816 17863 4202496 88298 2206 0 0 5026 59 0 0 20 0 2 0 28637434 482361344 85007 18446744073709551615 140170587095040 140170591402392 140733312447872 140733312439632 140170555840075 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22160/statm: 117764 85007 7143 1052 0 96334 0 [pid=22160/tid=22165] ppid=22159 vsize=471056 CPUtime=48.82 /proc/22160/task/22165/stat : 22165 (aptitude) R 22159 22160 17863 34816 17863 4202560 73635 2206 0 0 4831 51 0 0 20 0 2 0 28637480 482361344 85007 18446744073709551615 140170587095040 140170591402392 140733312447872 140170490492392 140170544605511 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 50.85 Current children cumulated vsize (KiB) 471056 [startup+102.3 s] /proc/loadavg: 1.03 1.03 1.00 2/57 22166 /proc/meminfo: memFree=157036/1022884 swapFree=0/0 [pid=22160] ppid=22159 vsize=912612 CPUtime=101.81 /proc/22160/stat : 22160 (aptitude) S 22159 22160 17863 34816 17863 4202496 198650 2206 0 0 10063 118 0 0 20 0 2 0 28637434 934514688 195358 18446744073709551615 140170587095040 140170591402392 140733312447872 140733312439632 140170555840075 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22160/statm: 228153 195358 7144 1052 0 206723 0 [pid=22160/tid=22165] ppid=22159 vsize=912612 CPUtime=99.77 /proc/22160/task/22165/stat : 22165 (aptitude) R 22159 22160 17863 34816 17863 4202560 183987 2206 0 0 9867 110 0 0 20 0 2 0 28637480 934514688 195358 18446744073709551615 140170587095040 140170591402392 140733312447872 140170490494696 140170589691578 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 101.81 Current children cumulated vsize (KiB) 912612 Maximum VSize exceeded: sending signal-name then SIGKILL [startup+130.5 s] /proc/loadavg: 1.16 1.06 1.01 2/57 22166 /proc/meminfo: memFree=10120/1022884 swapFree=0/0 [pid=22160] ppid=22159 vsize=1151136 CPUtime=127.42 /proc/22160/stat : 22160 (aptitude) S 22159 22160 17863 34816 17863 4202496 259445 2206 344 0 12591 151 0 0 20 0 2 0 28637434 1178763264 247084 18446744073709551615 140170587095040 140170591402392 140733312447872 140733312439632 140170555840075 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22160/statm: 287817 247094 6328 1052 0 266387 0 [pid=22160/tid=22165] ppid=22159 vsize=1151268 CPUtime=125.38 /proc/22160/task/22165/stat : 22165 (aptitude) R 22159 22160 17863 34816 17863 4202560 244792 2206 344 0 12395 143 0 0 20 0 2 0 28637480 1178898432 247094 18446744073709551615 140170587095040 140170591402392 140733312447872 140170490492488 140170544605280 0 134217728 4096 0 0 0 0 -1 0 0 0 219 0 0 Current children cumulated CPU time (s) 127.42 Current children cumulated vsize (KiB) 1151136 Sending Terminated to process tree (bottom up) Sleeping 2 seconds Solver just ended. Dumping a history of the last processes samples [startup+130.5 s] /proc/loadavg: 1.16 1.06 1.01 2/57 22166 /proc/meminfo: memFree=10120/1022884 swapFree=0/0 [pid=22160] ppid=22159 vsize=1151136 CPUtime=127.42 /proc/22160/stat : 22160 (aptitude) S 22159 22160 17863 34816 17863 4202496 259445 2206 344 0 12591 151 0 0 20 0 2 0 28637434 1178763264 247084 18446744073709551615 140170587095040 140170591402392 140733312447872 140733312439632 140170555840075 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22160/statm: 287817 247094 6328 1052 0 266387 0 [pid=22160/tid=22165] ppid=22159 vsize=1151268 CPUtime=125.38 /proc/22160/task/22165/stat : 22165 (aptitude) R 22159 22160 17863 34816 17863 4202560 244792 2206 344 0 12395 143 0 0 20 0 2 0 28637480 1178898432 247094 18446744073709551615 140170587095040 140170591402392 140733312447872 140170490492488 140170544605280 0 134217728 4096 0 0 0 0 -1 0 0 0 219 0 0 Current children cumulated CPU time (s) 127.42 Current children cumulated vsize (KiB) 1151136 Child ended because it received signal 15 (SIGTERM) Real time (s): 130.655 CPU time (s): 127.556 CPU user time (s): 125.96 CPU system time (s): 1.5961 CPU usage (%): 97.6282 Max. virtual memory (cumulated for all children) (KiB): 1151136 getrusage(RUSAGE_CHILDREN,...) data: user time used= 125.96 system time used= 1.5961 maximum resident set size= 992512 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 261740 page faults= 346 swaps= 0 block input operations= 17904 block output operations= 56 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 731 involuntary context switches= 2628 runsolver used 0.196012 second user time and 0.412025 second system time The end