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/28.runsolver.aptitude aptitude -s -y --without-recommends install libpils-dev scigraphica wogerman bluez-pcmcia-support libperl4caml-ocaml-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.00 1.02 0.87 2/55 21083 /proc/meminfo: memFree=904000/1022884 swapFree=0/0 [pid=21083] ppid=21082 vsize=3152 CPUtime=0 /proc/21083/stat : 21083 (runsolver) R 21082 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28360424 3227648 33 18446744073709551615 134512640 134586868 4287342768 4287340816 4151219248 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/21083/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.198188 s] /proc/loadavg: 1.00 1.02 0.87 2/55 21083 /proc/meminfo: memFree=904000/1022884 swapFree=0/0 [pid=21083] ppid=21082 vsize=89152 CPUtime=0.18 /proc/21083/stat : 21083 (aptitude) R 21082 21083 17863 34816 17863 4202496 7870 1711 0 0 17 1 0 0 20 0 1 0 28360424 91291648 7662 18446744073709551615 139747914244096 139747918551448 140734916860192 140734916849968 139747909097384 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/21083/statm: 22288 7662 6726 1052 0 858 0 Current children cumulated CPU time (s) 0.18 Current children cumulated vsize (KiB) 89152 [startup+0.200276 s] /proc/loadavg: 1.00 1.02 0.87 2/55 21083 /proc/meminfo: memFree=904000/1022884 swapFree=0/0 [pid=21083] ppid=21082 vsize=89152 CPUtime=0.19 /proc/21083/stat : 21083 (aptitude) R 21082 21083 17863 34816 17863 4202496 7870 1711 0 0 18 1 0 0 20 0 1 0 28360424 91291648 7662 18446744073709551615 139747914244096 139747918551448 140734916860192 140734916849968 139747909092951 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/21083/statm: 22288 7662 6726 1052 0 858 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 89152 [startup+0.300244 s] /proc/loadavg: 1.00 1.02 0.87 2/55 21083 /proc/meminfo: memFree=904000/1022884 swapFree=0/0 [pid=21083] ppid=21082 vsize=101864 CPUtime=0.29 /proc/21083/stat : 21083 (aptitude) R 21082 21083 17863 34816 17863 4202496 11709 1711 0 0 27 2 0 0 20 0 1 0 28360424 104308736 10756 18446744073709551615 139747914244096 139747918551448 140734916860192 140734916849624 139747917169669 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/21083/statm: 25466 10756 6746 1052 0 4036 0 Current children cumulated CPU time (s) 0.29 Current children cumulated vsize (KiB) 101864 [startup+0.700207 s] /proc/loadavg: 1.00 1.02 0.87 2/55 21083 /proc/meminfo: memFree=904000/1022884 swapFree=0/0 [pid=21083] ppid=21082 vsize=114164 CPUtime=0.68 /proc/21083/stat : 21083 (aptitude) R 21082 21083 17863 34816 17863 4202496 13719 1711 0 0 66 2 0 0 20 0 2 0 28360424 116903936 12090 18446744073709551615 139747914244096 139747918551448 140734916860192 140734916851464 139747915872594 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21083/statm: 28541 12090 6977 1052 0 7111 0 Current children cumulated CPU time (s) 0.68 Current children cumulated vsize (KiB) 114164 [startup+1.50024 s] /proc/loadavg: 1.00 1.02 0.87 2/57 21088 /proc/meminfo: memFree=883284/1022884 swapFree=0/0 [pid=21083] ppid=21082 vsize=115288 CPUtime=1.47 /proc/21083/stat : 21083 (aptitude) R 21082 21083 17863 34816 17863 4202496 14499 2214 0 0 143 4 0 0 20 0 2 0 28360424 118054912 12278 18446744073709551615 139747914244096 139747918551448 140734916860192 140734916852216 139747880549356 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21083/statm: 28822 12278 7066 1052 0 7392 0 [pid=21083/tid=21088] ppid=21082 vsize=115288 CPUtime=0 /proc/21083/task/21088/stat : 21088 (aptitude) S 21082 21083 17863 34816 17863 4202560 6 2214 0 0 0 0 0 0 20 0 2 0 28360469 118054912 12278 18446744073709551615 139747914244096 139747918551448 140734916860192 139747817650176 139747882988244 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 1.47 Current children cumulated vsize (KiB) 115288 [startup+3.10024 s] /proc/loadavg: 1.00 1.02 0.87 2/57 21089 /proc/meminfo: memFree=872868/1022884 swapFree=0/0 [pid=21083] ppid=21082 vsize=137996 CPUtime=3.07 /proc/21083/stat : 21083 (aptitude) S 21082 21083 17863 34816 17863 4202496 20941 2214 0 0 300 7 0 0 20 0 2 0 28360424 141307904 18198 18446744073709551615 139747914244096 139747918551448 140734916860192 140734916851952 139747882989131 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21083/statm: 34499 18198 7122 1052 0 13069 0 [pid=21083/tid=21088] ppid=21082 vsize=137996 CPUtime=1.15 /proc/21083/task/21088/stat : 21088 (aptitude) R 21082 21083 17863 34816 17863 4202560 6409 2214 0 0 113 2 0 0 20 0 2 0 28360469 141307904 18198 18446744073709551615 139747914244096 139747918551448 140734916860192 139747817641544 139747917004020 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) 137996 [startup+6.30024 s] /proc/loadavg: 1.00 1.02 0.87 2/57 21089 /proc/meminfo: memFree=825624/1022884 swapFree=0/0 [pid=21083] ppid=21082 vsize=247236 CPUtime=6.25 /proc/21083/stat : 21083 (aptitude) S 21082 21083 17863 34816 17863 4202496 32368 2214 0 0 614 11 0 0 20 0 2 0 28360424 253169664 29151 18446744073709551615 139747914244096 139747918551448 140734916860192 140734916851952 139747882989131 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21083/statm: 61809 29151 7123 1052 0 40379 0 [pid=21083/tid=21088] ppid=21082 vsize=247236 CPUtime=4.34 /proc/21083/task/21088/stat : 21088 (aptitude) R 21082 21083 17863 34816 17863 4202560 17835 2214 0 0 428 6 0 0 20 0 2 0 28360469 253169664 29151 18446744073709551615 139747914244096 139747918551448 140734916860192 139747817643752 139747871754567 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) 247236 [startup+12.7002 s] /proc/loadavg: 1.00 1.02 0.87 2/57 21089 /proc/meminfo: memFree=758416/1022884 swapFree=0/0 [pid=21083] ppid=21082 vsize=307484 CPUtime=12.63 /proc/21083/stat : 21083 (aptitude) S 21082 21083 17863 34816 17863 4202496 47402 2214 0 0 1243 20 0 0 20 0 2 0 28360424 314863616 44180 18446744073709551615 139747914244096 139747918551448 140734916860192 140734916851952 139747882989131 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21083/statm: 76871 44180 7123 1052 0 55441 0 [pid=21083/tid=21088] ppid=21082 vsize=307484 CPUtime=10.71 /proc/21083/task/21088/stat : 21088 (aptitude) R 21082 21083 17863 34816 17863 4202560 32869 2214 0 0 1056 15 0 0 20 0 2 0 28360469 314863616 44180 18446744073709551615 139747914244096 139747918551448 140734916860192 139747817643704 139747916952133 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) 307484 [startup+25.5003 s] /proc/loadavg: 1.00 1.02 0.87 2/57 21089 /proc/meminfo: memFree=671492/1022884 swapFree=0/0 [pid=21083] ppid=21082 vsize=393312 CPUtime=25.36 /proc/21083/stat : 21083 (aptitude) S 21082 21083 17863 34816 17863 4202496 68889 2214 0 0 2505 31 0 0 20 0 2 0 28360424 402751488 65635 18446744073709551615 139747914244096 139747918551448 140734916860192 140734916851952 139747882989131 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21083/statm: 98328 65635 7124 1052 0 76898 0 [pid=21083/tid=21088] ppid=21082 vsize=393312 CPUtime=23.44 /proc/21083/task/21088/stat : 21088 (aptitude) R 21082 21083 17863 34816 17863 4202560 54356 2214 0 0 2318 26 0 0 20 0 2 0 28360469 402751488 65635 18446744073709551615 139747914244096 139747918551448 140734916860192 139747817643608 139747871739783 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) 393312 [startup+51.1003 s] /proc/loadavg: 1.00 1.02 0.87 2/57 21089 /proc/meminfo: memFree=450028/1022884 swapFree=0/0 [pid=21083] ppid=21082 vsize=617520 CPUtime=50.83 /proc/21083/stat : 21083 (aptitude) S 21082 21083 17863 34816 17863 4202496 124912 2214 0 0 5021 62 0 0 20 0 2 0 28360424 632340480 121658 18446744073709551615 139747914244096 139747918551448 140734916860192 140734916851952 139747882989131 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21083/statm: 154380 121658 7138 1052 0 132950 0 [pid=21083/tid=21088] ppid=21082 vsize=617520 CPUtime=48.91 /proc/21083/task/21088/stat : 21088 (aptitude) R 21082 21083 17863 34816 17863 4202560 110373 2214 0 0 4834 57 0 0 20 0 2 0 28360469 632340480 121658 18446744073709551615 139747914244096 139747918551448 140734916860192 139747817641496 139747871754573 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0 Current children cumulated CPU time (s) 50.83 Current children cumulated vsize (KiB) 617520 [startup+102.3 s] /proc/loadavg: 1.00 1.01 0.88 2/57 21089 /proc/meminfo: memFree=8084/1022884 swapFree=0/0 [pid=21083] ppid=21082 vsize=1062088 CPUtime=101.65 /proc/21083/stat : 21083 (aptitude) S 21082 21083 17863 34816 17863 4202496 236013 2214 0 0 10039 126 0 0 20 0 2 0 28360424 1087578112 232759 18446744073709551615 139747914244096 139747918551448 140734916860192 140734916851952 139747882989131 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21083/statm: 265522 232759 7138 1052 0 244092 0 [pid=21083/tid=21088] ppid=21082 vsize=1062088 CPUtime=99.72 /proc/21083/task/21088/stat : 21088 (aptitude) R 21082 21083 17863 34816 17863 4202560 221474 2214 0 0 9851 121 0 0 20 0 2 0 28360469 1087578112 232759 18446744073709551615 139747914244096 139747918551448 140734916860192 139747817643608 139747916828926 0 134217728 4096 0 0 0 0 -1 0 0 0 15 0 0 Current children cumulated CPU time (s) 101.65 Current children cumulated vsize (KiB) 1062088 Maximum VSize exceeded: sending signal-name then SIGKILL [startup+114.4 s] /proc/loadavg: 1.14 1.04 0.89 2/57 21089 /proc/meminfo: memFree=10140/1022884 swapFree=0/0 [pid=21083] ppid=21082 vsize=1153796 CPUtime=111.74 /proc/21083/stat : 21083 (aptitude) S 21082 21083 17863 34816 17863 4202496 258932 2214 261 0 11038 136 0 0 20 0 2 0 28360424 1181487104 244646 18446744073709551615 139747914244096 139747918551448 140734916860192 140734916851952 139747882989131 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21083/statm: 288449 244646 6812 1052 0 267019 0 [pid=21083/tid=21088] ppid=21082 vsize=1153796 CPUtime=109.82 /proc/21083/task/21088/stat : 21088 (aptitude) R 21082 21083 17863 34816 17863 4202560 244386 2214 256 0 10850 132 0 0 20 0 2 0 28360469 1181487104 244646 18446744073709551615 139747914244096 139747918551448 140734916860192 139747817645592 139747872396584 0 134217728 4096 0 0 0 0 -1 0 0 0 173 0 0 Current children cumulated CPU time (s) 111.74 Current children cumulated vsize (KiB) 1153796 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): 114.532 CPU time (s): 111.891 CPU user time (s): 110.451 CPU system time (s): 1.44009 CPU usage (%): 97.6944 Max. virtual memory (cumulated for all children) (KiB): 1153796 getrusage(RUSAGE_CHILDREN,...) data: user time used= 110.451 system time used= 1.44009 maximum resident set size= 982672 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 261196 page faults= 262 swaps= 0 block input operations= 16384 block output operations= 160 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 590 involuntary context switches= 2605 runsolver used 0.124007 second user time and 0.396024 second system time The end