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/24.runsolver.aptitude aptitude -s -y --without-recommends install libheap-perl lapack-pic cecilia multicd sound-recorder 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 Current StackSize limit: 8192 KiB [startup+0 s] /proc/loadavg: 1.07 1.08 1.02 2/55 23109 /proc/meminfo: memFree=948036/1022884 swapFree=0/0 [pid=23109] ppid=23108 vsize=3152 CPUtime=0 /proc/23109/stat : 23109 (runsolver) R 23108 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28828703 3227648 32 18446744073709551615 134512640 134586868 4288231568 4288229616 4151866416 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/23109/statm: 788 32 0 19 0 73 0 [startup+0.135499 s] /proc/loadavg: 1.07 1.08 1.02 2/55 23109 /proc/meminfo: memFree=948036/1022884 swapFree=0/0 [pid=23109] ppid=23108 vsize=28716 CPUtime=0 /proc/23109/stat : 23109 (aptitude) D 23108 23109 17863 34816 17863 4202496 156 0 11 0 0 0 0 0 20 0 1 0 28828703 29405184 78 18446744073709551615 139789412909056 139789417216408 140733436796064 140733436792680 139789410768419 0 0 0 0 0 0 0 17 0 0 0 12 0 0 /proc/23109/statm: 7179 78 50 1052 0 33 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 28716 [startup+0.200373 s] /proc/loadavg: 1.07 1.08 1.02 2/55 23109 /proc/meminfo: memFree=948036/1022884 swapFree=0/0 [pid=23109] ppid=23108 vsize=40832 CPUtime=0 /proc/23109/stat : 23109 (aptitude) D 23108 23109 17863 34816 17863 4202496 178 0 16 0 0 0 0 0 20 0 1 0 28828703 41811968 101 18446744073709551615 139789412909056 139789417216408 140733436796064 140733436792488 139789410768419 0 0 0 0 0 0 0 17 0 0 0 19 0 0 /proc/23109/statm: 10208 101 63 1052 0 60 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 40832 [startup+0.300355 s] /proc/loadavg: 1.07 1.08 1.02 2/55 23109 /proc/meminfo: memFree=948036/1022884 swapFree=0/0 [pid=23109] ppid=23108 vsize=61308 CPUtime=0 /proc/23109/stat : 23109 (aptitude) D 23108 23109 17863 34816 17863 4202496 1141 0 27 0 0 0 0 0 20 0 1 0 28828703 62779392 1050 18446744073709551615 139789412909056 139789417216408 140733436796064 140733436788856 139789410768419 0 134217728 4096 0 0 0 0 17 0 0 0 28 0 0 /proc/23109/statm: 15327 1050 875 1052 0 108 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 61308 [startup+0.700204 s] /proc/loadavg: 1.07 1.08 1.02 2/55 23109 /proc/meminfo: memFree=948036/1022884 swapFree=0/0 [pid=23109] ppid=23108 vsize=100508 CPUtime=0.08 /proc/23109/stat : 23109 (aptitude) R 23108 23109 17863 34816 17863 4202496 9973 1705 72 2 5 2 1 0 20 0 1 0 28828703 102920192 9846 18446744073709551615 139789412909056 139789417216408 140733436796064 140733436787328 139789407753040 0 134217728 4096 0 0 0 0 17 0 0 0 59 0 0 /proc/23109/statm: 25127 9846 8671 1052 0 1122 0 Current children cumulated CPU time (s) 0.08 Current children cumulated vsize (KiB) 100508 [startup+1.5002 s] /proc/loadavg: 1.07 1.08 1.02 2/56 23113 /proc/meminfo: memFree=918756/1022884 swapFree=0/0 [pid=23109] ppid=23108 vsize=119772 CPUtime=0.58 /proc/23109/stat : 23109 (aptitude) R 23108 23109 17863 34816 17863 4202496 16431 1705 74 2 50 7 1 0 20 0 1 0 28828703 122646528 14783 18446744073709551615 139789412909056 139789417216408 140733436796064 140733436785496 139789407809331 0 134217728 4096 0 0 0 0 17 0 0 0 89 0 0 /proc/23109/statm: 29943 14783 9317 1052 0 5938 0 Current children cumulated CPU time (s) 0.58 Current children cumulated vsize (KiB) 119772 [startup+3.10025 s] /proc/loadavg: 1.07 1.08 1.02 2/57 23114 /proc/meminfo: memFree=847572/1022884 swapFree=0/0 [pid=23109] ppid=23108 vsize=132516 CPUtime=1.9 /proc/23109/stat : 23109 (aptitude) R 23108 23109 17863 34816 17863 4202496 19400 1705 74 2 178 11 1 0 20 0 2 0 28828703 135696384 16743 18446744073709551615 139789412909056 139789417216408 140733436796064 140733436783224 139789379218496 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 117 0 0 /proc/23109/statm: 33129 16743 9586 1052 0 9124 0 [pid=23109/tid=23114] ppid=23108 vsize=132516 CPUtime=0.01 /proc/23109/task/23114/stat : 23114 (aptitude) S 23108 23109 17863 34816 17863 4202560 4 1705 0 2 0 0 1 0 20 0 2 0 28828890 135696384 16743 18446744073709551615 139789412909056 139789417216408 140733436796064 139789303736320 139789381653204 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 1.9 Current children cumulated vsize (KiB) 132516 heavy processes: [startup+6.30024 s] /proc/loadavg: 1.07 1.08 1.02 2/57 23115 /proc/meminfo: memFree=811860/1022884 swapFree=0/0 [pid=23109] ppid=23108 vsize=237264 CPUtime=5.06 /proc/23109/stat : 23109 (aptitude) S 23108 23109 17863 34816 17863 4202496 30737 2201 74 4 485 20 1 0 20 0 2 0 28828703 242958336 26651 18446744073709551615 139789412909056 139789417216408 140733436796064 140733436787824 139789381654091 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 117 0 0 /proc/23109/statm: 59316 26651 9700 1052 0 35311 0 [pid=23109/tid=23114] ppid=23108 vsize=237264 CPUtime=1.94 /proc/23109/task/23114/stat : 23114 (aptitude) R 23108 23109 17863 34816 17863 4202560 10219 2201 0 4 189 4 1 0 20 0 2 0 28828890 242958336 26651 18446744073709551615 139789412909056 139789417216408 140733436796064 139789303729848 139789381649955 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 5.06 Current children cumulated vsize (KiB) 237264 [startup+12.7002 s] /proc/loadavg: 1.06 1.08 1.02 1/57 23115 /proc/meminfo: memFree=758416/1022884 swapFree=0/0 [pid=23109] ppid=23108 vsize=277376 CPUtime=11.34 /proc/23109/stat : 23109 (aptitude) R 23108 23109 17863 34816 17863 4202496 43902 2201 87 4 1106 27 1 0 20 0 2 0 28828703 284033024 36900 18446744073709551615 139789412909056 139789417216408 140733436796064 140733436785824 139789370612022 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 124 0 0 /proc/23109/statm: 69344 36900 9749 1052 0 45332 0 [pid=23109/tid=23114] ppid=23108 vsize=277376 CPUtime=7.7 /proc/23109/task/23114/stat : 23114 (aptitude) S 23108 23109 17863 34816 17863 4202560 20639 2201 1 4 761 8 1 0 20 0 2 0 28828890 284033024 36900 18446744073709551615 139789412909056 139789417216408 140733436796064 139789303736320 139789381653204 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0 Current children cumulated CPU time (s) 11.34 Current children cumulated vsize (KiB) 277376 Solver just ended. Dumping a history of the last processes samples [startup+12.8003 s] /proc/loadavg: 1.06 1.08 1.02 1/57 23115 /proc/meminfo: memFree=758416/1022884 swapFree=0/0 [pid=23109] ppid=23108 vsize=277376 CPUtime=11.44 /proc/23109/stat : 23109 (aptitude) R 23108 23109 17863 34816 17863 4202496 44136 2700 87 4 1110 32 1 1 20 0 2 0 28828703 284033024 36988 18446744073709551615 139789412909056 139789417216408 140733436796064 140733436786312 139789370753093 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 124 0 0 /proc/23109/statm: 69344 36988 9749 1052 0 45332 0 [pid=23109/tid=23114] ppid=23108 vsize=277376 CPUtime=7.71 /proc/23109/task/23114/stat : 23114 (aptitude) S 23108 23109 17863 34816 17863 4202560 20639 2700 1 4 761 8 1 1 20 0 2 0 28828890 284033024 36988 18446744073709551615 139789412909056 139789417216408 140733436796064 139789303736320 139789381653204 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0 Current children cumulated CPU time (s) 11.44 Current children cumulated vsize (KiB) 277376 [startup+13.0003 s] /proc/loadavg: 1.06 1.08 1.02 1/57 23115 /proc/meminfo: memFree=758416/1022884 swapFree=0/0 [pid=23109] ppid=23108 vsize=141872 CPUtime=11.55 /proc/23109/stat : 23109 (aptitude) D 23108 23109 17863 34816 17863 4202496 44669 2700 102 4 1117 36 1 1 20 0 1 0 28828703 145276928 2951 18446744073709551615 139789412909056 139789417216408 140733436796064 140733436795136 139789391399680 0 134217728 4096 0 0 0 0 17 0 0 0 133 0 0 /proc/23109/statm: 35468 2951 1528 1052 0 19724 0 Current children cumulated CPU time (s) 11.55 Current children cumulated vsize (KiB) 141872 Child status: 0 Real time (s): 13.01 CPU time (s): 11.5647 CPU user time (s): 11.1847 CPU system time (s): 0.380023 CPU usage (%): 88.891 Max. virtual memory (cumulated for all children) (KiB): 277376 getrusage(RUSAGE_CHILDREN,...) data: user time used= 11.1847 system time used= 0.380023 maximum resident set size= 148100 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 47387 page faults= 108 swaps= 0 block input operations= 166752 block output operations= 136 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 1578 involuntary context switches= 252 runsolver used 0.028001 second user time and 0.040002 second system time The end