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/104.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends remove libatk1.0-dev libkpimidentities1 kdebase-bin libvte4 openoffice.org-debian-files 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.00 1.00 2/55 6333 /proc/meminfo: memFree=577196/1022884 swapFree=0/0 [pid=6333] ppid=6332 vsize=3152 CPUtime=0 /proc/6333/stat : 6333 (runsolver) R 6332 17872 17872 34816 17872 4202560 0 0 0 0 0 0 0 0 20 0 1 0 31289401 3227648 33 18446744073709551615 134512640 134586868 4288733168 4288731216 4152124464 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/6333/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.175094 s] /proc/loadavg: 1.00 1.00 1.00 2/55 6333 /proc/meminfo: memFree=577196/1022884 swapFree=0/0 [pid=6333] ppid=6332 vsize=34832 CPUtime=0.2 /proc/6333/stat : 6333 (cupt) R 6332 6333 17872 34816 17872 4202496 2190 7203 0 0 11 2 6 1 20 0 1 0 31289401 35667968 2008 18446744073709551615 4194304 5184042 140733708748112 140733708745304 140085279262095 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6333/statm: 8708 2008 729 242 0 1270 0 Current children cumulated CPU time (s) 0.2 Current children cumulated vsize (KiB) 34832 [startup+0.200261 s] /proc/loadavg: 1.00 1.00 1.00 2/55 6333 /proc/meminfo: memFree=577196/1022884 swapFree=0/0 [pid=6333] ppid=6332 vsize=35492 CPUtime=0.22 /proc/6333/stat : 6333 (cupt) R 6332 6333 17872 34816 17872 4202496 2356 7203 0 0 12 3 6 1 20 0 1 0 31289401 36343808 2174 18446744073709551615 4194304 5184042 140733708748112 140733708745304 140085270806645 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6333/statm: 8873 2174 729 242 0 1435 0 Current children cumulated CPU time (s) 0.22 Current children cumulated vsize (KiB) 35492 [startup+0.300254 s] /proc/loadavg: 1.00 1.00 1.00 2/55 6333 /proc/meminfo: memFree=577196/1022884 swapFree=0/0 [pid=6333] ppid=6332 vsize=38116 CPUtime=0.32 /proc/6333/stat : 6333 (cupt) R 6332 6333 17872 34816 17872 4202496 3056 7203 0 0 21 4 6 1 20 0 1 0 31289401 39030784 2811 18446744073709551615 4194304 5184042 140733708748112 140733708745304 140085270675694 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6333/statm: 9529 2811 739 242 0 2091 0 Current children cumulated CPU time (s) 0.32 Current children cumulated vsize (KiB) 38116 [startup+0.700201 s] /proc/loadavg: 1.00 1.00 1.00 2/55 6333 /proc/meminfo: memFree=577196/1022884 swapFree=0/0 [pid=6333] ppid=6332 vsize=63700 CPUtime=0.73 /proc/6333/stat : 6333 (cupt) R 6332 6333 17872 34816 17872 4202496 9578 7203 0 0 54 12 6 1 20 0 1 0 31289401 65228800 9323 18446744073709551615 4194304 5184042 140733708748112 140733708745416 140085287107978 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6333/statm: 15925 9323 850 242 0 8487 0 Current children cumulated CPU time (s) 0.73 Current children cumulated vsize (KiB) 63700 [startup+1.50019 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6353 /proc/meminfo: memFree=542716/1022884 swapFree=0/0 [pid=6333] ppid=6332 vsize=67748 CPUtime=1.51 /proc/6333/stat : 6333 (cupt) R 6332 6333 17872 34816 17872 4202496 10731 7203 0 0 132 12 6 1 20 0 1 0 31289401 69373952 10282 18446744073709551615 4194304 5184042 140733708748112 140733708745416 140085270741516 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6333/statm: 16937 10282 851 242 0 9499 0 Current children cumulated CPU time (s) 1.51 Current children cumulated vsize (KiB) 67748 [startup+3.10021 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6353 /proc/meminfo: memFree=538376/1022884 swapFree=0/0 [pid=6333] ppid=6332 vsize=69072 CPUtime=3.11 /proc/6333/stat : 6333 (cupt) R 6332 6333 17872 34816 17872 4202496 11252 7203 0 0 292 12 6 1 20 0 1 0 31289401 70729728 10546 18446744073709551615 4194304 5184042 140733708748112 140733708742360 140085287085600 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6333/statm: 17268 10546 851 242 0 9830 0 Current children cumulated CPU time (s) 3.11 Current children cumulated vsize (KiB) 69072 [startup+6.3002 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6353 /proc/meminfo: memFree=537012/1022884 swapFree=0/0 [pid=6333] ppid=6332 vsize=71860 CPUtime=6.3 /proc/6333/stat : 6333 (cupt) R 6332 6333 17872 34816 17872 4202496 12213 7203 0 0 610 13 6 1 20 0 1 0 31289401 73584640 10994 18446744073709551615 4194304 5184042 140733708748112 140733708745416 140085287085581 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6333/statm: 17965 10994 851 242 0 10527 0 Current children cumulated CPU time (s) 6.3 Current children cumulated vsize (KiB) 71860 [startup+12.7002 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6353 /proc/meminfo: memFree=535028/1022884 swapFree=0/0 [pid=6333] ppid=6332 vsize=75956 CPUtime=12.67 /proc/6333/stat : 6333 (cupt) R 6332 6333 17872 34816 17872 4202496 13639 7203 0 0 1246 14 6 1 20 0 1 0 31289401 77778944 11395 18446744073709551615 4194304 5184042 140733708748112 140733708745544 140085287085600 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6333/statm: 18989 11395 851 242 0 11551 0 Current children cumulated CPU time (s) 12.67 Current children cumulated vsize (KiB) 75956 [startup+25.5002 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6353 /proc/meminfo: memFree=531804/1022884 swapFree=0/0 [pid=6333] ppid=6332 vsize=75956 CPUtime=25.41 /proc/6333/stat : 6333 (cupt) R 6332 6333 17872 34816 17872 4202496 14440 7203 0 0 2520 14 6 1 20 0 1 0 31289401 77778944 12196 18446744073709551615 4194304 5184042 140733708748112 140733708745544 140085287085622 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6333/statm: 18989 12196 851 242 0 11551 0 Current children cumulated CPU time (s) 25.41 Current children cumulated vsize (KiB) 75956 [startup+51.1002 s] /proc/loadavg: 1.07 1.02 1.00 2/56 6577 /proc/meminfo: memFree=524488/1022884 swapFree=0/0 [pid=6333] ppid=6332 vsize=85344 CPUtime=47.99 /proc/6333/stat : 6333 (cupt) R 6332 6333 17872 34816 17872 4202496 18159 7203 0 0 4775 17 6 1 20 0 1 0 31289401 87392256 13866 18446744073709551615 4194304 5184042 140733708748112 140733708745416 140085279262080 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6333/statm: 21336 13866 851 242 0 13898 0 Current children cumulated CPU time (s) 47.99 Current children cumulated vsize (KiB) 85344 [startup+102.3 s] /proc/loadavg: 1.03 1.01 1.00 2/56 6577 /proc/meminfo: memFree=502788/1022884 swapFree=0/0 [pid=6333] ppid=6332 vsize=114780 CPUtime=98.99 /proc/6333/stat : 6333 (cupt) R 6332 6333 17872 34816 17872 4202496 27669 7203 0 0 9870 22 6 1 20 0 1 0 31289401 117534720 19279 18446744073709551615 4194304 5184042 140733708748112 140733708744808 140085287085780 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6333/statm: 28695 19279 851 242 0 21257 0 Current children cumulated CPU time (s) 98.99 Current children cumulated vsize (KiB) 114780 Solver just ended. Dumping a history of the last processes samples [startup+102.403 s] /proc/loadavg: 1.03 1.01 1.00 2/56 6577 /proc/meminfo: memFree=502788/1022884 swapFree=0/0 [pid=6333] ppid=6332 vsize=114920 CPUtime=99.09 /proc/6333/stat : 6333 (cupt) R 6332 6333 17872 34816 17872 4202496 27679 7203 0 0 9880 22 6 1 20 0 1 0 31289401 117678080 19289 18446744073709551615 4194304 5184042 140733708748112 140733708744808 140085287085584 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6333/statm: 28730 19289 851 242 0 21292 0 Current children cumulated CPU time (s) 99.09 Current children cumulated vsize (KiB) 114920 [startup+115.2 s] /proc/loadavg: 1.02 1.01 1.00 2/56 6577 /proc/meminfo: memFree=498944/1022884 swapFree=0/0 [pid=6333] ppid=6332 vsize=116996 CPUtime=111.84 /proc/6333/stat : 6333 (cupt) R 6332 6333 17872 34816 17872 4202496 28626 7203 0 0 11153 24 6 1 20 0 1 0 31289401 119803904 20236 18446744073709551615 4194304 5184042 140733708748112 140733708745416 140085287085581 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6333/statm: 29249 20236 851 242 0 21811 0 Current children cumulated CPU time (s) 111.84 Current children cumulated vsize (KiB) 116996 [startup+128 s] /proc/loadavg: 1.02 1.01 1.00 2/56 6577 /proc/meminfo: memFree=493984/1022884 swapFree=0/0 [pid=6333] ppid=6332 vsize=120500 CPUtime=124.58 /proc/6333/stat : 6333 (cupt) R 6332 6333 17872 34816 17872 4202496 29943 7203 0 0 12427 24 6 1 20 0 1 0 31289401 123392000 21553 18446744073709551615 4194304 5184042 140733708748112 140733708745416 140085287143043 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6333/statm: 30125 21553 851 242 0 22687 0 Current children cumulated CPU time (s) 124.58 Current children cumulated vsize (KiB) 120500 [startup+134.4 s] /proc/loadavg: 1.02 1.01 1.00 2/56 6577 /proc/meminfo: memFree=487908/1022884 swapFree=0/0 [pid=6333] ppid=6332 vsize=125576 CPUtime=130.95 /proc/6333/stat : 6333 (cupt) R 6332 6333 17872 34816 17872 4202496 31430 7203 0 0 13064 24 6 1 20 0 1 0 31289401 128589824 23040 18446744073709551615 4194304 5184042 140733708748112 140733708745416 140085287085683 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6333/statm: 31394 23040 851 242 0 23956 0 Current children cumulated CPU time (s) 130.95 Current children cumulated vsize (KiB) 125576 [startup+137.603 s] /proc/loadavg: 1.01 1.01 1.00 2/56 6577 /proc/meminfo: memFree=486792/1022884 swapFree=0/0 [pid=6333] ppid=6332 vsize=126288 CPUtime=134.15 /proc/6333/stat : 6333 (cupt) R 6332 6333 17872 34816 17872 4202496 31693 7203 0 0 13384 24 6 1 20 0 1 0 31289401 129318912 23303 18446744073709551615 4194304 5184042 140733708748112 140733708745416 140085287085619 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6333/statm: 31572 23303 851 242 0 24134 0 Current children cumulated CPU time (s) 134.15 Current children cumulated vsize (KiB) 126288 [startup+138.4 s] /proc/loadavg: 1.01 1.01 1.00 2/56 6577 /proc/meminfo: memFree=486792/1022884 swapFree=0/0 [pid=6333] ppid=6332 vsize=126572 CPUtime=134.94 /proc/6333/stat : 6333 (cupt) R 6332 6333 17872 34816 17872 4202496 31783 7203 0 0 13463 24 6 1 20 0 1 0 31289401 129609728 23393 18446744073709551615 4194304 5184042 140733708748112 140733708745416 140085287031837 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6333/statm: 31643 23393 851 242 0 24205 0 Current children cumulated CPU time (s) 134.94 Current children cumulated vsize (KiB) 126572 [startup+139.2 s] /proc/loadavg: 1.01 1.01 1.00 2/56 6577 /proc/meminfo: memFree=486296/1022884 swapFree=0/0 [pid=6333] ppid=6332 vsize=126572 CPUtime=135.74 /proc/6333/stat : 6333 (cupt) R 6332 6333 17872 34816 17872 4202496 31798 7203 0 0 13543 24 6 1 20 0 1 0 31289401 129609728 23408 18446744073709551615 4194304 5184042 140733708748112 140733708745416 140085287143085 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6333/statm: 31643 23408 851 242 0 24205 0 Current children cumulated CPU time (s) 135.74 Current children cumulated vsize (KiB) 126572 [startup+139.6 s] /proc/loadavg: 1.01 1.01 1.00 2/56 6577 /proc/meminfo: memFree=486296/1022884 swapFree=0/0 [pid=6333] ppid=6332 vsize=93800 CPUtime=136.14 /proc/6333/stat : 6333 (cupt) R 6332 6333 17872 34816 17872 4202496 31815 7203 0 0 13582 25 6 1 20 0 1 0 31289401 96051200 16862 18446744073709551615 4194304 5184042 140733708748112 140733708746488 140085270732235 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6333/statm: 23450 16862 862 242 0 16012 0 Current children cumulated CPU time (s) 136.14 Current children cumulated vsize (KiB) 93800 Child status: 1 Real time (s): 139.684 CPU time (s): 136.237 CPU user time (s): 135.957 CPU system time (s): 0.280017 CPU usage (%): 97.5321 Max. virtual memory (cumulated for all children) (KiB): 126572 getrusage(RUSAGE_CHILDREN,...) data: user time used= 135.956 system time used= 0.280017 maximum resident set size= 93700 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 39038 page faults= 0 swaps= 0 block input operations= 0 block output operations= 96 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 52 involuntary context switches= 3095 runsolver used 0 second user time and 0.568035 second system time The end