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/59.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends install bonobo-conf gdis ooo2dbk python-optik libmon-perl 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.02 1.02 1.00 2/55 4588 /proc/meminfo: memFree=580864/1022884 swapFree=0/0 [pid=4588] ppid=4587 vsize=3152 CPUtime=0 /proc/4588/stat : 4588 (runsolver) R 4587 17872 17872 34816 17872 4202560 0 0 0 0 0 0 0 0 20 0 1 0 30580510 3227648 32 18446744073709551615 134512640 134586868 4292504432 4292502480 4152050736 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/4588/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.140862 s] /proc/loadavg: 1.02 1.02 1.00 2/55 4588 /proc/meminfo: memFree=580864/1022884 swapFree=0/0 [pid=4588] ppid=4587 vsize=34168 CPUtime=0.16 /proc/4588/stat : 4588 (cupt) R 4587 4588 17872 34816 17872 4202496 2016 7217 0 0 9 0 4 3 20 0 1 0 30580510 34988032 1835 18446744073709551615 4194304 5184042 140735751229632 140735751226824 140081495400560 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4588/statm: 8542 1835 729 242 0 1104 0 Current children cumulated CPU time (s) 0.16 Current children cumulated vsize (KiB) 34168 [startup+0.200289 s] /proc/loadavg: 1.02 1.02 1.00 2/55 4588 /proc/meminfo: memFree=580864/1022884 swapFree=0/0 [pid=4588] ppid=4587 vsize=35624 CPUtime=0.22 /proc/4588/stat : 4588 (cupt) R 4587 4588 17872 34816 17872 4202496 2389 7217 0 0 14 1 4 3 20 0 1 0 30580510 36478976 2207 18446744073709551615 4194304 5184042 140735751229632 140735751226824 140081495680752 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4588/statm: 8906 2207 729 242 0 1468 0 Current children cumulated CPU time (s) 0.22 Current children cumulated vsize (KiB) 35624 [startup+0.300305 s] /proc/loadavg: 1.02 1.02 1.00 2/55 4588 /proc/meminfo: memFree=580864/1022884 swapFree=0/0 [pid=4588] ppid=4587 vsize=38252 CPUtime=0.32 /proc/4588/stat : 4588 (cupt) R 4587 4588 17872 34816 17872 4202496 3092 7217 0 0 23 2 4 3 20 0 1 0 30580510 39170048 2846 18446744073709551615 4194304 5184042 140735751229632 140735751226824 140081495680752 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4588/statm: 9563 2846 739 242 0 2125 0 Current children cumulated CPU time (s) 0.32 Current children cumulated vsize (KiB) 38252 [startup+0.700192 s] /proc/loadavg: 1.02 1.02 1.00 2/55 4588 /proc/meminfo: memFree=580864/1022884 swapFree=0/0 [pid=4588] ppid=4587 vsize=65744 CPUtime=0.73 /proc/4588/stat : 4588 (cupt) R 4587 4588 17872 34816 17872 4202496 10093 7217 0 0 58 8 4 3 20 0 1 0 30580510 67321856 9839 18446744073709551615 4194304 5184042 140735751229632 140735751226824 140081511761880 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4588/statm: 16436 9839 851 242 0 8998 0 Current children cumulated CPU time (s) 0.73 Current children cumulated vsize (KiB) 65744 [startup+1.5002 s] /proc/loadavg: 1.02 1.02 1.00 2/56 4608 /proc/meminfo: memFree=543788/1022884 swapFree=0/0 [pid=4588] ppid=4587 vsize=67360 CPUtime=1.52 /proc/4588/stat : 4588 (cupt) R 4587 4588 17872 34816 17872 4202496 10648 7217 0 0 137 8 4 3 20 0 1 0 30580510 68976640 10200 18446744073709551615 4194304 5184042 140735751229632 140735751226936 140081511695219 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4588/statm: 16840 10200 851 242 0 9402 0 Current children cumulated CPU time (s) 1.52 Current children cumulated vsize (KiB) 67360 [startup+3.1002 s] /proc/loadavg: 1.02 1.02 1.00 2/56 4608 /proc/meminfo: memFree=542672/1022884 swapFree=0/0 [pid=4588] ppid=4587 vsize=68384 CPUtime=3.11 /proc/4588/stat : 4588 (cupt) R 4587 4588 17872 34816 17872 4202496 11043 7217 0 0 296 8 4 3 20 0 1 0 30580510 70025216 10338 18446744073709551615 4194304 5184042 140735751229632 140735751227064 140081511678976 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4588/statm: 17096 10338 851 242 0 9658 0 Current children cumulated CPU time (s) 3.11 Current children cumulated vsize (KiB) 68384 [startup+6.3002 s] /proc/loadavg: 1.02 1.02 1.00 2/56 4608 /proc/meminfo: memFree=541680/1022884 swapFree=0/0 [pid=4588] ppid=4587 vsize=70432 CPUtime=6.29 /proc/4588/stat : 4588 (cupt) R 4587 4588 17872 34816 17872 4202496 11815 7217 0 0 614 8 4 3 20 0 1 0 30580510 72122368 10597 18446744073709551615 4194304 5184042 140735751229632 140735751227064 140081511686536 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4588/statm: 17608 10597 851 242 0 10170 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 70432 [startup+12.7002 s] /proc/loadavg: 1.02 1.02 1.00 2/56 4608 /proc/meminfo: memFree=539572/1022884 swapFree=0/0 [pid=4588] ppid=4587 vsize=74528 CPUtime=12.67 /proc/4588/stat : 4588 (cupt) R 4587 4588 17872 34816 17872 4202496 13359 7217 0 0 1251 9 4 3 20 0 1 0 30580510 76316672 11116 18446744073709551615 4194304 5184042 140735751229632 140735751227064 140081503760892 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4588/statm: 18632 11116 851 242 0 11194 0 Current children cumulated CPU time (s) 12.67 Current children cumulated vsize (KiB) 74528 [startup+25.5002 s] /proc/loadavg: 1.01 1.02 1.00 2/56 4608 /proc/meminfo: memFree=535480/1022884 swapFree=0/0 [pid=4588] ppid=4587 vsize=82720 CPUtime=25.42 /proc/4588/stat : 4588 (cupt) R 4587 4588 17872 34816 17872 4202496 16459 7217 0 0 2523 12 4 3 20 0 1 0 30580510 84705280 12167 18446744073709551615 4194304 5184042 140735751229632 140735751227064 140081511678990 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4588/statm: 20680 12167 851 242 0 13242 0 Current children cumulated CPU time (s) 25.42 Current children cumulated vsize (KiB) 82720 Solver just ended. Dumping a history of the last processes samples [startup+25.6003 s] /proc/loadavg: 1.01 1.02 1.00 2/56 4608 /proc/meminfo: memFree=535480/1022884 swapFree=0/0 [pid=4588] ppid=4587 vsize=82720 CPUtime=25.52 /proc/4588/stat : 4588 (cupt) R 4587 4588 17872 34816 17872 4202496 16467 7217 0 0 2533 12 4 3 20 0 1 0 30580510 84705280 12175 18446744073709551615 4194304 5184042 140735751229632 140735751227064 140081511737011 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4588/statm: 20680 12175 851 242 0 13242 0 Current children cumulated CPU time (s) 25.52 Current children cumulated vsize (KiB) 82720 [startup+32.0031 s] /proc/loadavg: 1.01 1.02 1.00 2/56 4608 /proc/meminfo: memFree=533372/1022884 swapFree=0/0 [pid=4588] ppid=4587 vsize=82720 CPUtime=31.89 /proc/4588/stat : 4588 (cupt) R 4587 4588 17872 34816 17872 4202496 16999 7217 0 0 3170 12 4 3 20 0 1 0 30580510 84705280 12707 18446744073709551615 4194304 5184042 140735751229632 140735751227064 140081495335410 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4588/statm: 20680 12707 851 242 0 13242 0 Current children cumulated CPU time (s) 31.89 Current children cumulated vsize (KiB) 82720 [startup+35.2002 s] /proc/loadavg: 1.01 1.02 1.00 2/56 4608 /proc/meminfo: memFree=532256/1022884 swapFree=0/0 [pid=4588] ppid=4587 vsize=82720 CPUtime=35.08 /proc/4588/stat : 4588 (cupt) R 4587 4588 17872 34816 17872 4202496 17262 7217 0 0 3489 12 4 3 20 0 1 0 30580510 84705280 12970 18446744073709551615 4194304 5184042 140735751229632 140735751227064 140081511679410 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4588/statm: 20680 12970 851 242 0 13242 0 Current children cumulated CPU time (s) 35.08 Current children cumulated vsize (KiB) 82720 [startup+38.4002 s] /proc/loadavg: 1.01 1.02 1.00 2/56 4608 /proc/meminfo: memFree=531512/1022884 swapFree=0/0 [pid=4588] ppid=4587 vsize=82720 CPUtime=38.27 /proc/4588/stat : 4588 (cupt) R 4587 4588 17872 34816 17872 4202496 17525 7217 0 0 3807 13 4 3 20 0 1 0 30580510 84705280 13233 18446744073709551615 4194304 5184042 140735751229632 140735751227064 140081511679496 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4588/statm: 20680 13233 851 242 0 13242 0 Current children cumulated CPU time (s) 38.27 Current children cumulated vsize (KiB) 82720 [startup+39.2002 s] /proc/loadavg: 1.01 1.02 1.00 2/56 4608 /proc/meminfo: memFree=531140/1022884 swapFree=0/0 [pid=4588] ppid=4587 vsize=82720 CPUtime=39.07 /proc/4588/stat : 4588 (cupt) R 4587 4588 17872 34816 17872 4202496 17603 7217 0 0 3887 13 4 3 20 0 1 0 30580510 84705280 13311 18446744073709551615 4194304 5184042 140735751229632 140735751227064 140081495336825 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4588/statm: 20680 13311 851 242 0 13242 0 Current children cumulated CPU time (s) 39.07 Current children cumulated vsize (KiB) 82720 [startup+39.6002 s] /proc/loadavg: 1.01 1.02 1.00 2/56 4608 /proc/meminfo: memFree=530396/1022884 swapFree=0/0 [pid=4588] ppid=4587 vsize=82720 CPUtime=39.46 /proc/4588/stat : 4588 (cupt) R 4587 4588 17872 34816 17872 4202496 17685 7217 0 0 3926 13 4 3 20 0 1 0 30580510 84705280 13393 18446744073709551615 4194304 5184042 140735751229632 140735751227064 140081511625745 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4588/statm: 20680 13393 851 242 0 13242 0 Current children cumulated CPU time (s) 39.46 Current children cumulated vsize (KiB) 82720 [startup+40.0002 s] /proc/loadavg: 1.01 1.02 1.00 2/56 4608 /proc/meminfo: memFree=530396/1022884 swapFree=0/0 [pid=4588] ppid=4587 vsize=82720 CPUtime=39.86 /proc/4588/stat : 4588 (cupt) R 4587 4588 17872 34816 17872 4202496 17751 7217 0 0 3966 13 4 3 20 0 1 0 30580510 84705280 13459 18446744073709551615 4194304 5184042 140735751229632 140735751223928 140081511679488 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4588/statm: 20680 13459 851 242 0 13242 0 Current children cumulated CPU time (s) 39.86 Current children cumulated vsize (KiB) 82720 [startup+40.1002 s] /proc/loadavg: 1.01 1.02 1.00 2/56 4608 /proc/meminfo: memFree=530396/1022884 swapFree=0/0 [pid=4588] ppid=4587 vsize=82720 CPUtime=39.96 /proc/4588/stat : 4588 (cupt) R 4587 4588 17872 34816 17872 4202496 17763 7217 0 0 3976 13 4 3 20 0 1 0 30580510 84705280 13471 18446744073709551615 4194304 5184042 140735751229632 140735751223928 140081495330690 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4588/statm: 20680 13471 851 242 0 13242 0 Current children cumulated CPU time (s) 39.96 Current children cumulated vsize (KiB) 82720 Child status: 1 Real time (s): 40.1742 CPU time (s): 40.0465 CPU user time (s): 39.8705 CPU system time (s): 0.176011 CPU usage (%): 99.6821 Max. virtual memory (cumulated for all children) (KiB): 82720 getrusage(RUSAGE_CHILDREN,...) data: user time used= 39.8705 system time used= 0.176011 maximum resident set size= 56340 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 25011 page faults= 0 swaps= 0 block input operations= 0 block output operations= 32 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 52 involuntary context switches= 618 runsolver used 0.16401 second user time and 0 second system time The end