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/49.runsolver.aptitude aptitude -s -y --without-recommends install pathogen contact-lookup-applet libdbd-pg-perl exim gnusound 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.08 1.05 2/55 25643 /proc/meminfo: memFree=834304/1022884 swapFree=0/0 [pid=25643] ppid=25642 vsize=3152 CPUtime=0 /proc/25643/stat : 25643 (runsolver) R 25642 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29540454 3227648 32 18446744073709551615 134512640 134586868 4286650304 4286648352 4151764016 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/25643/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.157441 s] /proc/loadavg: 1.03 1.08 1.05 2/55 25643 /proc/meminfo: memFree=834304/1022884 swapFree=0/0 [pid=25643] ppid=25642 vsize=103288 CPUtime=0.14 /proc/25643/stat : 25643 (aptitude) R 25642 25643 17863 34816 17863 4202496 11285 1710 0 0 12 2 0 0 20 0 1 0 29540454 105766912 11085 18446744073709551615 140239434735616 140239439042968 140733384921088 140733384912352 140239430135345 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25643/statm: 25822 11085 9873 1052 0 1159 0 Current children cumulated CPU time (s) 0.14 Current children cumulated vsize (KiB) 103288 [startup+0.200284 s] /proc/loadavg: 1.03 1.08 1.05 2/55 25643 /proc/meminfo: memFree=834304/1022884 swapFree=0/0 [pid=25643] ppid=25642 vsize=103288 CPUtime=0.18 /proc/25643/stat : 25643 (aptitude) R 25642 25643 17863 34816 17863 4202496 11301 1710 0 0 16 2 0 0 20 0 1 0 29540454 105766912 11101 18446744073709551615 140239434735616 140239439042968 140733384921088 140733384912352 140239429580655 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25643/statm: 25822 11101 9889 1052 0 1159 0 Current children cumulated CPU time (s) 0.18 Current children cumulated vsize (KiB) 103288 [startup+0.300288 s] /proc/loadavg: 1.03 1.08 1.05 2/55 25643 /proc/meminfo: memFree=834304/1022884 swapFree=0/0 [pid=25643] ppid=25642 vsize=103432 CPUtime=0.28 /proc/25643/stat : 25643 (aptitude) R 25642 25643 17863 34816 17863 4202496 11428 1710 0 0 26 2 0 0 20 0 1 0 29540454 105914368 11220 18446744073709551615 140239434735616 140239439042968 140733384921088 140733384910864 140239429552259 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25643/statm: 25858 11220 9956 1052 0 1195 0 Current children cumulated CPU time (s) 0.28 Current children cumulated vsize (KiB) 103432 [startup+0.700205 s] /proc/loadavg: 1.03 1.08 1.05 2/55 25643 /proc/meminfo: memFree=834304/1022884 swapFree=0/0 [pid=25643] ppid=25642 vsize=123068 CPUtime=0.68 /proc/25643/stat : 25643 (aptitude) R 25642 25643 17863 34816 17863 4202496 17689 1710 0 0 62 6 0 0 20 0 1 0 29540454 126021632 15965 18446744073709551615 140239434735616 140239439042968 140733384921088 140733384910520 140239403491696 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25643/statm: 30767 15965 9976 1052 0 6104 0 Current children cumulated CPU time (s) 0.68 Current children cumulated vsize (KiB) 123068 [startup+1.50029 s] /proc/loadavg: 1.03 1.08 1.05 2/57 25648 /proc/meminfo: memFree=814332/1022884 swapFree=0/0 [pid=25643] ppid=25642 vsize=136072 CPUtime=1.48 /proc/25643/stat : 25643 (aptitude) R 25642 25643 17863 34816 17863 4202496 20649 1710 0 0 141 7 0 0 20 0 2 0 29540454 139337728 17567 18446744073709551615 140239434735616 140239439042968 140733384921088 140733384912360 140239392317137 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25643/statm: 34018 17567 10207 1052 0 9355 0 [pid=25643/tid=25648] ppid=25642 vsize=136072 CPUtime=0 /proc/25643/task/25648/stat : 25648 (aptitude) S 25642 25643 17863 34816 17863 4202560 4 1710 0 0 0 0 0 0 20 0 2 0 29540531 139337728 17567 18446744073709551615 140239434735616 140239439042968 140733384921088 140239322413056 140239403479764 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) 136072 [startup+3.10027 s] /proc/loadavg: 1.02 1.07 1.05 2/57 25648 /proc/meminfo: memFree=804164/1022884 swapFree=0/0 [pid=25643] ppid=25642 vsize=137828 CPUtime=3.07 /proc/25643/stat : 25643 (aptitude) R 25642 25643 17863 34816 17863 4202496 21994 2208 0 0 297 10 0 0 20 0 2 0 29540454 141135872 17933 18446744073709551615 140239434735616 140239439042968 140733384921088 140733384907792 140239437735003 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25643/statm: 34457 17933 10303 1052 0 9794 0 [pid=25643/tid=25648] ppid=25642 vsize=137828 CPUtime=0 /proc/25643/task/25648/stat : 25648 (aptitude) S 25642 25643 17863 34816 17863 4202560 6 2208 0 0 0 0 0 0 20 0 2 0 29540531 141135872 17933 18446744073709551615 140239434735616 140239439042968 140733384921088 140239322413056 140239403479764 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) 137828 [startup+6.30026 s] /proc/loadavg: 1.02 1.07 1.05 2/57 25649 /proc/meminfo: memFree=762748/1022884 swapFree=0/0 [pid=25643] ppid=25642 vsize=185484 CPUtime=6.25 /proc/25643/stat : 25643 (aptitude) S 25642 25643 17863 34816 17863 4202496 34953 2208 0 0 613 12 0 0 20 0 2 0 29540454 189935616 30103 18446744073709551615 140239434735616 140239439042968 140733384921088 140733384912848 140239403480651 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25643/statm: 46371 30103 10359 1052 0 21708 0 [pid=25643/tid=25648] ppid=25642 vsize=185484 CPUtime=2.85 /proc/25643/task/25648/stat : 25648 (aptitude) R 25642 25643 17863 34816 17863 4202560 12959 2208 0 0 283 2 0 0 20 0 2 0 29540531 189935616 30103 18446744073709551615 140239434735616 140239439042968 140733384921088 140239322404376 140239437537536 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) 185484 [startup+12.7003 s] /proc/loadavg: 1.02 1.07 1.05 2/57 25649 /proc/meminfo: memFree=707940/1022884 swapFree=0/0 [pid=25643] ppid=25642 vsize=302336 CPUtime=12.62 /proc/25643/stat : 25643 (aptitude) S 25642 25643 17863 34816 17863 4202496 47805 2208 0 0 1240 22 0 0 20 0 2 0 29540454 309592064 42899 18446744073709551615 140239434735616 140239439042968 140733384921088 140733384912848 140239403480651 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25643/statm: 75584 42899 10359 1052 0 50921 0 [pid=25643/tid=25648] ppid=25642 vsize=302336 CPUtime=9.22 /proc/25643/task/25648/stat : 25648 (aptitude) R 25642 25643 17863 34816 17863 4202560 25810 2208 0 0 911 11 0 0 20 0 2 0 29540531 309592064 42899 18446744073709551615 140239434735616 140239439042968 140733384921088 140239322406584 140239437381914 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) 302336 [startup+25.5003 s] /proc/loadavg: 1.02 1.07 1.05 2/57 25649 /proc/meminfo: memFree=613080/1022884 swapFree=0/0 [pid=25643] ppid=25642 vsize=394004 CPUtime=25.36 /proc/25643/stat : 25643 (aptitude) S 25642 25643 17863 34816 17863 4202496 70942 2208 0 0 2507 29 0 0 20 0 2 0 29540454 403460096 65781 18446744073709551615 140239434735616 140239439042968 140733384921088 140733384912848 140239403480651 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25643/statm: 98501 65781 10360 1052 0 73838 0 [pid=25643/tid=25648] ppid=25642 vsize=394004 CPUtime=21.96 /proc/25643/task/25648/stat : 25648 (aptitude) R 25642 25643 17863 34816 17863 4202560 48947 2208 0 0 2177 19 0 0 20 0 2 0 29540531 403460096 65781 18446744073709551615 140239434735616 140239439042968 140733384921088 140239322404376 140239437562382 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) 394004 [startup+51.1003 s] /proc/loadavg: 1.01 1.06 1.04 2/57 25649 /proc/meminfo: memFree=479036/1022884 swapFree=0/0 [pid=25643] ppid=25642 vsize=528608 CPUtime=50.83 /proc/25643/stat : 25643 (aptitude) S 25642 25643 17863 34816 17863 4202496 105016 2208 0 0 5037 46 0 0 20 0 2 0 29540454 541294592 99480 18446744073709551615 140239434735616 140239439042968 140733384921088 140733384912848 140239403480651 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25643/statm: 132152 99480 10374 1052 0 107489 0 [pid=25643/tid=25648] ppid=25642 vsize=528608 CPUtime=47.43 /proc/25643/task/25648/stat : 25648 (aptitude) R 25642 25643 17863 34816 17863 4202560 83015 2208 0 0 4707 36 0 0 20 0 2 0 29540531 541294592 99480 18446744073709551615 140239434735616 140239439042968 140733384921088 140239322407304 140239437381914 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0 Current children cumulated CPU time (s) 50.83 Current children cumulated vsize (KiB) 528608 [startup+102.3 s] /proc/loadavg: 1.00 1.05 1.04 2/57 25649 /proc/meminfo: memFree=79756/1022884 swapFree=0/0 [pid=25643] ppid=25642 vsize=925380 CPUtime=101.78 /proc/25643/stat : 25643 (aptitude) S 25642 25643 17863 34816 17863 4202496 204122 2208 0 0 10086 92 0 0 20 0 2 0 29540454 947589120 198492 18446744073709551615 140239434735616 140239439042968 140733384921088 140733384912848 140239403480651 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25643/statm: 231345 198492 10375 1052 0 206682 0 [pid=25643/tid=25648] ppid=25642 vsize=925380 CPUtime=98.38 /proc/25643/task/25648/stat : 25648 (aptitude) R 25642 25643 17863 34816 17863 4202560 182121 2208 0 0 9756 82 0 0 20 0 2 0 29540531 947589120 198492 18446744073709551615 140239434735616 140239439042968 140733384921088 140239322404728 140239437350052 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0 Current children cumulated CPU time (s) 101.78 Current children cumulated vsize (KiB) 925380 Maximum VSize exceeded: sending signal-name then SIGKILL [startup+130 s] /proc/loadavg: 1.28 1.11 1.06 2/57 25649 /proc/meminfo: memFree=8936/1022884 swapFree=0/0 [pid=25643] ppid=25642 vsize=1151220 CPUtime=126.17 /proc/25643/stat : 25643 (aptitude) S 25642 25643 17863 34816 17863 4202496 260934 2208 384 0 12485 132 0 0 20 0 2 0 29540454 1178849280 245993 18446744073709551615 140239434735616 140239439042968 140733384921088 140733384912848 140239403480651 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25643/statm: 287805 245993 9641 1052 0 263142 0 [pid=25643/tid=25648] ppid=25642 vsize=1151220 CPUtime=122.77 /proc/25643/task/25648/stat : 25648 (aptitude) R 25642 25643 17863 34816 17863 4202560 238929 2208 384 0 12155 122 0 0 20 0 2 0 29540531 1178849280 245993 18446744073709551615 140239434735616 140239439042968 140733384921088 140239322407080 140239400661360 0 134217728 4096 0 0 0 0 -1 0 0 0 296 0 0 Current children cumulated CPU time (s) 126.17 Current children cumulated vsize (KiB) 1151220 Sending Terminated to process tree (bottom up) Sleeping 2 seconds Solver just ended. Dumping a history of the last processes samples [startup+130 s] /proc/loadavg: 1.28 1.11 1.06 2/57 25649 /proc/meminfo: memFree=8936/1022884 swapFree=0/0 [pid=25643] ppid=25642 vsize=1151220 CPUtime=126.17 /proc/25643/stat : 25643 (aptitude) S 25642 25643 17863 34816 17863 4202496 260934 2208 384 0 12485 132 0 0 20 0 2 0 29540454 1178849280 245993 18446744073709551615 140239434735616 140239439042968 140733384921088 140733384912848 140239403480651 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25643/statm: 287805 245993 9641 1052 0 263142 0 [pid=25643/tid=25648] ppid=25642 vsize=1151220 CPUtime=122.77 /proc/25643/task/25648/stat : 25648 (aptitude) R 25642 25643 17863 34816 17863 4202560 238929 2208 384 0 12155 122 0 0 20 0 2 0 29540531 1178849280 245993 18446744073709551615 140239434735616 140239439042968 140733384921088 140239322407080 140239400661360 0 134217728 4096 0 0 0 0 -1 0 0 0 296 0 0 Current children cumulated CPU time (s) 126.17 Current children cumulated vsize (KiB) 1151220 Child ended because it received signal 15 (SIGTERM) Real time (s): 130.172 CPU time (s): 126.348 CPU user time (s): 124.94 CPU system time (s): 1.40809 CPU usage (%): 97.062 Max. virtual memory (cumulated for all children) (KiB): 1151220 getrusage(RUSAGE_CHILDREN,...) data: user time used= 124.94 system time used= 1.40809 maximum resident set size= 986476 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 263263 page faults= 384 swaps= 0 block input operations= 17472 block output operations= 96 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 751 involuntary context switches= 2731 runsolver used 0.108006 second user time and 0.508031 second system time The end