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/85.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends install po-debiandoc kreversi decompyle libiw27 libneon24-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.12 1.02 1.00 2/55 5654 /proc/meminfo: memFree=578808/1022884 swapFree=0/0 [pid=5654] ppid=5653 vsize=3152 CPUtime=0 /proc/5654/stat : 5654 (runsolver) R 5653 17872 17872 34816 17872 4202560 0 0 0 0 0 0 0 0 20 0 1 0 30933177 3227648 32 18446744073709551615 134512640 134586868 4293607648 4293605696 4152140848 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/5654/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.122663 s] /proc/loadavg: 1.12 1.02 1.00 2/55 5654 /proc/meminfo: memFree=578808/1022884 swapFree=0/0 [pid=5654] ppid=5653 vsize=33508 CPUtime=0.13 /proc/5654/stat : 5654 (cupt) R 5653 5654 17872 34816 17872 4202496 1848 7205 0 0 5 2 4 2 20 0 1 0 30933177 34312192 1666 18446744073709551615 4194304 5184042 140733876308192 140733876305384 140606831451645 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5654/statm: 8377 1666 729 242 0 939 0 Current children cumulated CPU time (s) 0.13 Current children cumulated vsize (KiB) 33508 [startup+0.200274 s] /proc/loadavg: 1.12 1.02 1.00 2/55 5654 /proc/meminfo: memFree=578808/1022884 swapFree=0/0 [pid=5654] ppid=5653 vsize=35492 CPUtime=0.21 /proc/5654/stat : 5654 (cupt) R 5653 5654 17872 34816 17872 4202496 2345 7205 0 0 12 3 4 2 20 0 1 0 30933177 36343808 2162 18446744073709551615 4194304 5184042 140733876308192 140733876305384 140606847908342 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5654/statm: 8873 2162 729 242 0 1435 0 Current children cumulated CPU time (s) 0.21 Current children cumulated vsize (KiB) 35492 [startup+0.300275 s] /proc/loadavg: 1.12 1.02 1.00 2/55 5654 /proc/meminfo: memFree=578808/1022884 swapFree=0/0 [pid=5654] ppid=5653 vsize=37984 CPUtime=0.31 /proc/5654/stat : 5654 (cupt) R 5653 5654 17872 34816 17872 4202496 3048 7205 0 0 21 4 4 2 20 0 1 0 30933177 38895616 2802 18446744073709551615 4194304 5184042 140733876308192 140733876305384 140606831476876 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5654/statm: 9496 2802 739 242 0 2058 0 Current children cumulated CPU time (s) 0.31 Current children cumulated vsize (KiB) 37984 [startup+0.700195 s] /proc/loadavg: 1.12 1.02 1.00 2/55 5654 /proc/meminfo: memFree=578808/1022884 swapFree=0/0 [pid=5654] ppid=5653 vsize=65876 CPUtime=0.7 /proc/5654/stat : 5654 (cupt) R 5653 5654 17872 34816 17872 4202496 10121 7205 0 0 56 8 4 2 20 0 1 0 30933177 67457024 9866 18446744073709551615 4194304 5184042 140733876308192 140733876305432 140606847755248 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5654/statm: 16469 9866 851 242 0 9031 0 Current children cumulated CPU time (s) 0.7 Current children cumulated vsize (KiB) 65876 [startup+1.5002 s] /proc/loadavg: 1.11 1.02 1.00 2/56 5674 /proc/meminfo: memFree=540484/1022884 swapFree=0/0 [pid=5654] ppid=5653 vsize=68152 CPUtime=1.51 /proc/5654/stat : 5654 (cupt) R 5653 5654 17872 34816 17872 4202496 10834 7205 0 0 135 10 4 2 20 0 1 0 30933177 69787648 10385 18446744073709551615 4194304 5184042 140733876308192 140733876302440 140606848618878 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5654/statm: 17038 10385 851 242 0 9600 0 Current children cumulated CPU time (s) 1.51 Current children cumulated vsize (KiB) 68152 [startup+3.10015 s] /proc/loadavg: 1.11 1.02 1.00 2/56 5674 /proc/meminfo: memFree=538128/1022884 swapFree=0/0 [pid=5654] ppid=5653 vsize=71408 CPUtime=3.1 /proc/5654/stat : 5654 (cupt) R 5653 5654 17872 34816 17872 4202496 11795 7205 0 0 293 11 4 2 20 0 1 0 30933177 73121792 11089 18446744073709551615 4194304 5184042 140733876308192 140733876305496 140606847838048 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5654/statm: 17852 11089 851 242 0 10414 0 Current children cumulated CPU time (s) 3.1 Current children cumulated vsize (KiB) 71408 [startup+6.30021 s] /proc/loadavg: 1.11 1.02 1.00 2/56 5674 /proc/meminfo: memFree=534656/1022884 swapFree=0/0 [pid=5654] ppid=5653 vsize=76240 CPUtime=6.29 /proc/5654/stat : 5654 (cupt) R 5653 5654 17872 34816 17872 4202496 13217 7205 0 0 610 13 4 2 20 0 1 0 30933177 78069760 11998 18446744073709551615 4194304 5184042 140733876308192 140733876305496 140606847755680 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5654/statm: 19060 11998 851 242 0 11622 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 76240 [startup+12.7002 s] /proc/loadavg: 1.10 1.01 1.00 2/56 5674 /proc/meminfo: memFree=531060/1022884 swapFree=0/0 [pid=5654] ppid=5653 vsize=78112 CPUtime=12.66 /proc/5654/stat : 5654 (cupt) R 5653 5654 17872 34816 17872 4202496 14029 7205 0 0 1246 14 4 2 20 0 1 0 30933177 79986688 12810 18446744073709551615 4194304 5184042 140733876308192 140733876305496 140606847755264 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5654/statm: 19528 12810 851 242 0 12090 0 Current children cumulated CPU time (s) 12.66 Current children cumulated vsize (KiB) 78112 [startup+25.5002 s] /proc/loadavg: 1.08 1.01 1.00 2/56 5674 /proc/meminfo: memFree=523868/1022884 swapFree=0/0 [pid=5654] ppid=5653 vsize=85360 CPUtime=25.41 /proc/5654/stat : 5654 (cupt) R 5653 5654 17872 34816 17872 4202496 16831 7205 0 0 2515 20 4 2 20 0 1 0 30933177 87408640 14587 18446744073709551615 4194304 5184042 140733876308192 140733876302488 140606847804752 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5654/statm: 21340 14587 851 242 0 13902 0 Current children cumulated CPU time (s) 25.41 Current children cumulated vsize (KiB) 85360 Solver just ended. Dumping a history of the last processes samples [startup+25.6003 s] /proc/loadavg: 1.08 1.01 1.00 2/56 5674 /proc/meminfo: memFree=523868/1022884 swapFree=0/0 [pid=5654] ppid=5653 vsize=85360 CPUtime=25.51 /proc/5654/stat : 5654 (cupt) R 5653 5654 17872 34816 17872 4202496 16838 7205 0 0 2525 20 4 2 20 0 1 0 30933177 87408640 14594 18446744073709551615 4194304 5184042 140733876308192 140733876302488 140606847768402 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5654/statm: 21340 14594 851 242 0 13902 0 Current children cumulated CPU time (s) 25.51 Current children cumulated vsize (KiB) 85360 [startup+28.8002 s] /proc/loadavg: 1.07 1.01 1.00 2/56 5674 /proc/meminfo: memFree=521264/1022884 swapFree=0/0 [pid=5654] ppid=5653 vsize=95072 CPUtime=28.69 /proc/5654/stat : 5654 (cupt) R 5653 5654 17872 34816 17872 4202496 19471 7205 0 0 2842 21 4 2 20 0 1 0 30933177 97353728 15178 18446744073709551615 4194304 5184042 140733876308192 140733876305496 140606847755264 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5654/statm: 23768 15178 851 242 0 16330 0 Current children cumulated CPU time (s) 28.69 Current children cumulated vsize (KiB) 95072 [startup+32.0031 s] /proc/loadavg: 1.07 1.01 1.00 2/56 5674 /proc/meminfo: memFree=520396/1022884 swapFree=0/0 [pid=5654] ppid=5653 vsize=95340 CPUtime=31.88 /proc/5654/stat : 5654 (cupt) R 5653 5654 17872 34816 17872 4202496 19721 7205 0 0 3160 22 4 2 20 0 1 0 30933177 97628160 15428 18446744073709551615 4194304 5184042 140733876308192 140733876302440 140606847755710 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5654/statm: 23835 15428 851 242 0 16397 0 Current children cumulated CPU time (s) 31.88 Current children cumulated vsize (KiB) 95340 [startup+32.8002 s] /proc/loadavg: 1.07 1.01 1.00 2/56 5674 /proc/meminfo: memFree=520396/1022884 swapFree=0/0 [pid=5654] ppid=5653 vsize=95340 CPUtime=32.67 /proc/5654/stat : 5654 (cupt) R 5653 5654 17872 34816 17872 4202496 19769 7205 0 0 3239 22 4 2 20 0 1 0 30933177 97628160 15476 18446744073709551615 4194304 5184042 140733876308192 140733876302440 140606847755808 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5654/statm: 23835 15476 851 242 0 16397 0 Current children cumulated CPU time (s) 32.67 Current children cumulated vsize (KiB) 95340 [startup+33.2002 s] /proc/loadavg: 1.07 1.01 1.00 2/56 5674 /proc/meminfo: memFree=520148/1022884 swapFree=0/0 [pid=5654] ppid=5653 vsize=95340 CPUtime=33.07 /proc/5654/stat : 5654 (cupt) R 5653 5654 17872 34816 17872 4202496 19793 7205 0 0 3279 22 4 2 20 0 1 0 30933177 97628160 15500 18446744073709551615 4194304 5184042 140733876308192 140733876302440 140606847755424 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5654/statm: 23835 15500 851 242 0 16397 0 Current children cumulated CPU time (s) 33.07 Current children cumulated vsize (KiB) 95340 [startup+33.6002 s] /proc/loadavg: 1.07 1.01 1.00 2/56 5674 /proc/meminfo: memFree=520148/1022884 swapFree=0/0 [pid=5654] ppid=5653 vsize=78440 CPUtime=33.47 /proc/5654/stat : 5654 (cupt) R 5653 5654 17872 34816 17872 4202496 19824 7205 0 0 3318 23 4 2 20 0 1 0 30933177 80322560 13019 18446744073709551615 4194304 5184042 140733876308192 140733876307640 140606831402443 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5654/statm: 19610 13019 862 242 0 12172 0 Current children cumulated CPU time (s) 33.47 Current children cumulated vsize (KiB) 78440 Child status: 1 Real time (s): 33.6526 CPU time (s): 33.5461 CPU user time (s): 33.2661 CPU system time (s): 0.280017 CPU usage (%): 99.6835 Max. virtual memory (cumulated for all children) (KiB): 102984 getrusage(RUSAGE_CHILDREN,...) data: user time used= 33.2661 system time used= 0.280017 maximum resident set size= 68360 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 27049 page faults= 0 swaps= 0 block input operations= 0 block output operations= 8 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 52 involuntary context switches= 526 runsolver used 0.044002 second user time and 0.096006 second system time The end