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/152.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends remove kdbg libksieve0 libice-dev kwifimanager libart-2.0-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: 0.99 0.98 0.99 2/55 8333 /proc/meminfo: memFree=579064/1022884 swapFree=0/0 [pid=8333] ppid=8332 vsize=3152 CPUtime=0 /proc/8333/stat : 8333 (runsolver) R 8332 17872 17872 34816 17872 4202560 0 0 0 0 0 0 0 0 20 0 1 0 31946409 3227648 32 18446744073709551615 134512640 134586868 4288650464 4288648512 4151551024 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/8333/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.131287 s] /proc/loadavg: 0.99 0.98 0.99 2/55 8333 /proc/meminfo: memFree=579064/1022884 swapFree=0/0 [pid=8333] ppid=8332 vsize=33772 CPUtime=0.15 /proc/8333/stat : 8333 (cupt) R 8332 8333 17872 34816 17872 4202496 1905 7206 0 0 7 2 4 2 20 0 1 0 31946409 34582528 1723 18446744073709551615 4194304 5184042 140736436859248 140736436856440 140263485567000 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8333/statm: 8443 1723 729 242 0 1005 0 Current children cumulated CPU time (s) 0.15 Current children cumulated vsize (KiB) 33772 [startup+0.200272 s] /proc/loadavg: 0.99 0.98 0.99 2/55 8333 /proc/meminfo: memFree=579064/1022884 swapFree=0/0 [pid=8333] ppid=8332 vsize=35492 CPUtime=0.21 /proc/8333/stat : 8333 (cupt) R 8332 8333 17872 34816 17872 4202496 2343 7206 0 0 12 3 4 2 20 0 1 0 31946409 36343808 2160 18446744073709551615 4194304 5184042 140736436859248 140736436856440 140263502162963 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8333/statm: 8873 2160 729 242 0 1435 0 Current children cumulated CPU time (s) 0.21 Current children cumulated vsize (KiB) 35492 [startup+0.30026 s] /proc/loadavg: 0.99 0.98 0.99 2/55 8333 /proc/meminfo: memFree=579064/1022884 swapFree=0/0 [pid=8333] ppid=8332 vsize=37984 CPUtime=0.31 /proc/8333/stat : 8333 (cupt) R 8332 8333 17872 34816 17872 4202496 3050 7206 0 0 20 5 4 2 20 0 1 0 31946409 38895616 2804 18446744073709551615 4194304 5184042 140736436859248 140736436856440 140263485978352 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8333/statm: 9496 2804 739 242 0 2058 0 Current children cumulated CPU time (s) 0.31 Current children cumulated vsize (KiB) 37984 [startup+0.700201 s] /proc/loadavg: 0.99 0.98 0.99 2/55 8333 /proc/meminfo: memFree=579064/1022884 swapFree=0/0 [pid=8333] ppid=8332 vsize=65052 CPUtime=0.72 /proc/8333/stat : 8333 (cupt) R 8332 8333 17872 34816 17872 4202496 9904 7206 0 0 54 12 4 2 20 0 1 0 31946409 66613248 9648 18446744073709551615 4194304 5184042 140736436859248 140736436856504 140263501976995 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8333/statm: 16263 9648 851 242 0 8825 0 Current children cumulated CPU time (s) 0.72 Current children cumulated vsize (KiB) 65052 [startup+1.5002 s] /proc/loadavg: 0.99 0.98 0.99 2/56 8353 /proc/meminfo: memFree=542980/1022884 swapFree=0/0 [pid=8333] ppid=8332 vsize=66844 CPUtime=1.51 /proc/8333/stat : 8333 (cupt) R 8332 8333 17872 34816 17872 4202496 10598 7206 0 0 133 12 4 2 20 0 1 0 31946409 68448256 9891 18446744073709551615 4194304 5184042 140736436859248 140736436856696 140263501923726 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8333/statm: 16711 9891 851 242 0 9273 0 Current children cumulated CPU time (s) 1.51 Current children cumulated vsize (KiB) 66844 [startup+3.10021 s] /proc/loadavg: 0.99 0.98 0.99 2/56 8353 /proc/meminfo: memFree=541988/1022884 swapFree=0/0 [pid=8333] ppid=8332 vsize=69176 CPUtime=3.1 /proc/8333/stat : 8333 (cupt) R 8332 8333 17872 34816 17872 4202496 11606 7206 0 0 292 12 4 2 20 0 1 0 31946409 70836224 10386 18446744073709551615 4194304 5184042 140736436859248 140736436853544 140263501977213 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8333/statm: 17294 10386 851 242 0 9856 0 Current children cumulated CPU time (s) 3.1 Current children cumulated vsize (KiB) 69176 [startup+6.30021 s] /proc/loadavg: 0.99 0.98 0.99 2/56 8353 /proc/meminfo: memFree=539136/1022884 swapFree=0/0 [pid=8333] ppid=8332 vsize=70188 CPUtime=6.28 /proc/8333/stat : 8333 (cupt) R 8332 8333 17872 34816 17872 4202496 12100 7206 0 0 610 12 4 2 20 0 1 0 31946409 71872512 10880 18446744073709551615 4194304 5184042 140736436859248 140736436856552 140263501961973 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8333/statm: 17547 10880 851 242 0 10109 0 Current children cumulated CPU time (s) 6.28 Current children cumulated vsize (KiB) 70188 [startup+12.7002 s] /proc/loadavg: 0.99 0.98 0.99 2/56 8353 /proc/meminfo: memFree=537152/1022884 swapFree=0/0 [pid=8333] ppid=8332 vsize=74284 CPUtime=12.66 /proc/8333/stat : 8333 (cupt) R 8332 8333 17872 34816 17872 4202496 13585 7206 0 0 1247 13 4 2 20 0 1 0 31946409 76066816 11340 18446744073709551615 4194304 5184042 140736436859248 140736436856696 140263501977096 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8333/statm: 18571 11340 851 242 0 11133 0 Current children cumulated CPU time (s) 12.66 Current children cumulated vsize (KiB) 74284 [startup+25.5002 s] /proc/loadavg: 0.99 0.98 0.99 2/56 8353 /proc/meminfo: memFree=533432/1022884 swapFree=0/0 [pid=8333] ppid=8332 vsize=82476 CPUtime=25.4 /proc/8333/stat : 8333 (cupt) R 8332 8333 17872 34816 17872 4202496 16552 7206 0 0 2520 14 4 2 20 0 1 0 31946409 84455424 12258 18446744073709551615 4194304 5184042 140736436859248 140736436856680 140263502060818 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8333/statm: 20619 12258 851 242 0 13181 0 Current children cumulated CPU time (s) 25.4 Current children cumulated vsize (KiB) 82476 [startup+51.1002 s] /proc/loadavg: 1.06 1.00 1.00 2/56 8353 /proc/meminfo: memFree=525620/1022884 swapFree=0/0 [pid=8333] ppid=8332 vsize=98860 CPUtime=50.9 /proc/8333/stat : 8333 (cupt) R 8332 8333 17872 34816 17872 4202496 22511 7206 0 0 5066 18 4 2 20 0 1 0 31946409 101232640 14120 18446744073709551615 4194304 5184042 140736436859248 140736436856680 140263485643104 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8333/statm: 24715 14120 851 242 0 17277 0 Current children cumulated CPU time (s) 50.9 Current children cumulated vsize (KiB) 98860 [startup+102.3 s] /proc/loadavg: 1.02 1.00 1.00 2/56 8353 /proc/meminfo: memFree=510864/1022884 swapFree=0/0 [pid=8333] ppid=8332 vsize=98860 CPUtime=101.9 /proc/8333/stat : 8333 (cupt) R 8332 8333 17872 34816 17872 4202496 26240 7206 0 0 10161 23 4 2 20 0 1 0 31946409 101232640 17849 18446744073709551615 4194304 5184042 140736436859248 140736436856680 140263501977054 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8333/statm: 24715 17849 851 242 0 17277 0 Current children cumulated CPU time (s) 101.9 Current children cumulated vsize (KiB) 98860 Solver just ended. Dumping a history of the last processes samples [startup+102.403 s] /proc/loadavg: 1.02 1.00 1.00 2/56 8353 /proc/meminfo: memFree=510864/1022884 swapFree=0/0 [pid=8333] ppid=8332 vsize=98860 CPUtime=102 /proc/8333/stat : 8333 (cupt) R 8332 8333 17872 34816 17872 4202496 26247 7206 0 0 10171 23 4 2 20 0 1 0 31946409 101232640 17856 18446744073709551615 4194304 5184042 140736436859248 140736436856680 140263501976560 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8333/statm: 24715 17856 851 242 0 17277 0 Current children cumulated CPU time (s) 102 Current children cumulated vsize (KiB) 98860 [startup+115.2 s] /proc/loadavg: 1.02 1.00 1.00 2/56 8353 /proc/meminfo: memFree=507268/1022884 swapFree=0/0 [pid=8333] ppid=8332 vsize=131628 CPUtime=114.74 /proc/8333/stat : 8333 (cupt) R 8332 8333 17872 34816 17872 4202496 35377 7206 0 0 11442 26 4 2 20 0 1 0 31946409 134787072 18793 18446744073709551615 4194304 5184042 140736436859248 140736436856680 140263501976611 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8333/statm: 32907 18793 851 242 0 25469 0 Current children cumulated CPU time (s) 114.74 Current children cumulated vsize (KiB) 131628 [startup+121.6 s] /proc/loadavg: 1.02 1.00 1.00 2/56 8353 /proc/meminfo: memFree=505284/1022884 swapFree=0/0 [pid=8333] ppid=8332 vsize=131628 CPUtime=121.12 /proc/8333/stat : 8333 (cupt) R 8332 8333 17872 34816 17872 4202496 35847 7206 0 0 12079 27 4 2 20 0 1 0 31946409 134787072 19263 18446744073709551615 4194304 5184042 140736436859248 140736436856680 140263502060482 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8333/statm: 32907 19263 851 242 0 25469 0 Current children cumulated CPU time (s) 121.12 Current children cumulated vsize (KiB) 131628 [startup+128 s] /proc/loadavg: 1.01 1.00 1.00 2/56 8353 /proc/meminfo: memFree=503424/1022884 swapFree=0/0 [pid=8333] ppid=8332 vsize=131628 CPUtime=127.49 /proc/8333/stat : 8333 (cupt) R 8332 8333 17872 34816 17872 4202496 36310 7206 0 0 12715 28 4 2 20 0 1 0 31946409 134787072 19726 18446744073709551615 4194304 5184042 140736436859248 140736436856680 140263501976987 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8333/statm: 32907 19726 851 242 0 25469 0 Current children cumulated CPU time (s) 127.49 Current children cumulated vsize (KiB) 131628 [startup+131.2 s] /proc/loadavg: 1.01 1.00 1.00 2/56 8353 /proc/meminfo: memFree=502060/1022884 swapFree=0/0 [pid=8333] ppid=8332 vsize=131628 CPUtime=130.68 /proc/8333/stat : 8333 (cupt) R 8332 8333 17872 34816 17872 4202496 36662 7206 0 0 13034 28 4 2 20 0 1 0 31946409 134787072 20078 18446744073709551615 4194304 5184042 140736436859248 140736436856680 140263502060818 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8333/statm: 32907 20078 851 242 0 25469 0 Current children cumulated CPU time (s) 130.68 Current children cumulated vsize (KiB) 131628 [startup+132 s] /proc/loadavg: 1.01 1.00 1.00 2/56 8353 /proc/meminfo: memFree=501316/1022884 swapFree=0/0 [pid=8333] ppid=8332 vsize=131628 CPUtime=131.48 /proc/8333/stat : 8333 (cupt) R 8332 8333 17872 34816 17872 4202496 36806 7206 0 0 13114 28 4 2 20 0 1 0 31946409 134787072 20222 18446744073709551615 4194304 5184042 140736436859248 140736436856680 140263485633032 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8333/statm: 32907 20222 851 242 0 25469 0 Current children cumulated CPU time (s) 131.48 Current children cumulated vsize (KiB) 131628 [startup+132.4 s] /proc/loadavg: 1.01 1.00 1.00 2/56 8353 /proc/meminfo: memFree=501316/1022884 swapFree=0/0 [pid=8333] ppid=8332 vsize=131628 CPUtime=131.88 /proc/8333/stat : 8333 (cupt) R 8332 8333 17872 34816 17872 4202496 36882 7206 0 0 13153 29 4 2 20 0 1 0 31946409 134787072 20298 18446744073709551615 4194304 5184042 140736436859248 140736436856680 140263501951825 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8333/statm: 32907 20298 851 242 0 25469 0 Current children cumulated CPU time (s) 131.88 Current children cumulated vsize (KiB) 131628 [startup+132.801 s] /proc/loadavg: 1.01 1.00 1.00 2/56 8353 /proc/meminfo: memFree=501316/1022884 swapFree=0/0 [pid=8333] ppid=8332 vsize=131820 CPUtime=132.27 /proc/8333/stat : 8333 (cupt) R 8332 8333 17872 34816 17872 4202496 36963 7206 0 0 13192 29 4 2 20 0 1 0 31946409 134983680 16283 18446744073709551615 4194304 5184042 140736436859248 140736436857624 140263486013719 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8333/statm: 32955 16283 862 242 0 25517 0 Current children cumulated CPU time (s) 132.27 Current children cumulated vsize (KiB) 131820 Child status: 1 Real time (s): 132.849 CPU time (s): 132.344 CPU user time (s): 132.008 CPU system time (s): 0.336021 CPU usage (%): 99.6199 Max. virtual memory (cumulated for all children) (KiB): 164400 getrusage(RUSAGE_CHILDREN,...) data: user time used= 132.008 system time used= 0.336021 maximum resident set size= 105276 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 44189 page faults= 0 swaps= 0 block input operations= 0 block output operations= 480 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 52 involuntary context switches= 1939 runsolver used 0.248015 second user time and 0.292018 second system time The end