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/logs/45.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends install ftpgrab libtag1-doc libparams-validate-perl dovecot-common python-tclink 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.97 0.81 2/55 26399 /proc/meminfo: memFree=309356/1022884 swapFree=0/0 [pid=26399] ppid=26398 vsize=3152 CPUtime=0 /proc/26399/stat : 26399 (runsolver) R 26398 17872 17872 34816 17872 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28335083 3227648 33 18446744073709551615 134512640 134586868 4287684416 4287682464 4151444528 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/26399/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.178006 s] /proc/loadavg: 0.99 0.97 0.81 2/55 26399 /proc/meminfo: memFree=309356/1022884 swapFree=0/0 [pid=26399] ppid=26398 vsize=34832 CPUtime=0.2 /proc/26399/stat : 26399 (cupt) R 26398 26399 17872 34816 17872 4202496 2180 7200 0 0 11 2 4 3 20 0 1 0 28335083 35667968 1998 18446744073709551615 4194304 5184042 140734820701168 140734820698360 139737306345553 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26399/statm: 8708 1998 729 242 0 1270 0 Current children cumulated CPU time (s) 0.2 Current children cumulated vsize (KiB) 34832 [startup+0.200274 s] /proc/loadavg: 0.99 0.97 0.81 2/55 26399 /proc/meminfo: memFree=309356/1022884 swapFree=0/0 [pid=26399] ppid=26398 vsize=35360 CPUtime=0.22 /proc/26399/stat : 26399 (cupt) R 26398 26399 17872 34816 17872 4202496 2314 7200 0 0 12 3 4 3 20 0 1 0 28335083 36208640 2132 18446744073709551615 4194304 5184042 140734820701168 140734820698360 139737306345446 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26399/statm: 8840 2132 729 242 0 1402 0 Current children cumulated CPU time (s) 0.22 Current children cumulated vsize (KiB) 35360 [startup+0.300261 s] /proc/loadavg: 0.99 0.97 0.81 2/55 26399 /proc/meminfo: memFree=309356/1022884 swapFree=0/0 [pid=26399] ppid=26398 vsize=46880 CPUtime=0.31 /proc/26399/stat : 26399 (cupt) R 26398 26399 17872 34816 17872 4202496 5315 7200 0 0 20 4 4 3 20 0 1 0 28335083 48005120 5124 18446744073709551615 4194304 5184042 140734820701168 140734820695656 139737306414644 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26399/statm: 11720 5124 835 242 0 4282 0 Current children cumulated CPU time (s) 0.31 Current children cumulated vsize (KiB) 46880 [startup+0.7002 s] /proc/loadavg: 0.99 0.97 0.81 2/55 26399 /proc/meminfo: memFree=309356/1022884 swapFree=0/0 [pid=26399] ppid=26398 vsize=58632 CPUtime=0.72 /proc/26399/stat : 26399 (cupt) R 26398 26399 17872 34816 17872 4202496 8369 7200 0 0 59 6 4 3 20 0 1 0 28335083 60039168 8064 18446744073709551615 4194304 5184042 140734820701168 140734820698472 139737322740469 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26399/statm: 14658 8064 842 242 0 7220 0 Current children cumulated CPU time (s) 0.72 Current children cumulated vsize (KiB) 58632 [startup+1.50021 s] /proc/loadavg: 0.99 0.97 0.81 2/56 26419 /proc/meminfo: memFree=280092/1022884 swapFree=0/0 [pid=26399] ppid=26398 vsize=59400 CPUtime=1.51 /proc/26399/stat : 26399 (cupt) R 26398 26399 17872 34816 17872 4202496 8691 7200 0 0 138 6 4 3 20 0 1 0 28335083 60825600 8192 18446744073709551615 4194304 5184042 140734820701168 140734820698616 139737322755565 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26399/statm: 14850 8192 842 242 0 7412 0 Current children cumulated CPU time (s) 1.51 Current children cumulated vsize (KiB) 59400 [startup+3.10021 s] /proc/loadavg: 0.99 0.97 0.81 2/56 26419 /proc/meminfo: memFree=279100/1022884 swapFree=0/0 [pid=26399] ppid=26398 vsize=60424 CPUtime=3.11 /proc/26399/stat : 26399 (cupt) R 26398 26399 17872 34816 17872 4202496 9209 7200 0 0 298 6 4 3 20 0 1 0 28335083 61874176 8453 18446744073709551615 4194304 5184042 140734820701168 140734820698600 139737322755820 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26399/statm: 15106 8453 842 242 0 7668 0 Current children cumulated CPU time (s) 3.11 Current children cumulated vsize (KiB) 60424 [startup+6.3002 s] /proc/loadavg: 0.99 0.97 0.81 2/56 26419 /proc/meminfo: memFree=277364/1022884 swapFree=0/0 [pid=26399] ppid=26398 vsize=63236 CPUtime=6.29 /proc/26399/stat : 26399 (cupt) R 26398 26399 17872 34816 17872 4202496 10427 7200 0 0 616 6 4 3 20 0 1 0 28335083 64753664 9158 18446744073709551615 4194304 5184042 140734820701168 140734820698472 139737322729895 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26399/statm: 15809 9158 842 242 0 8371 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 63236 Solver just ended. Dumping a history of the last processes samples [startup+6.40027 s] /proc/loadavg: 0.99 0.97 0.81 2/56 26419 /proc/meminfo: memFree=277364/1022884 swapFree=0/0 [pid=26399] ppid=26398 vsize=63540 CPUtime=6.39 /proc/26399/stat : 26399 (cupt) R 26398 26399 17872 34816 17872 4202496 10518 7200 0 0 626 6 4 3 20 0 1 0 28335083 65064960 9249 18446744073709551615 4194304 5184042 140734820701168 140734820698472 139737322702155 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26399/statm: 15885 9249 842 242 0 8447 0 Current children cumulated CPU time (s) 6.39 Current children cumulated vsize (KiB) 63540 [startup+7.20021 s] /proc/loadavg: 0.99 0.97 0.81 2/56 26419 /proc/meminfo: memFree=274140/1022884 swapFree=0/0 [pid=26399] ppid=26398 vsize=71876 CPUtime=7.19 /proc/26399/stat : 26399 (cupt) R 26398 26399 17872 34816 17872 4202496 12773 7200 0 0 703 9 4 3 20 0 1 0 28335083 73601024 10479 18446744073709551615 4194304 5184042 140734820701168 140734820695464 139737322755152 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26399/statm: 17969 10479 842 242 0 10531 0 Current children cumulated CPU time (s) 7.19 Current children cumulated vsize (KiB) 71876 [startup+7.6002 s] /proc/loadavg: 0.99 0.97 0.81 2/56 26419 /proc/meminfo: memFree=274140/1022884 swapFree=0/0 [pid=26399] ppid=26398 vsize=71876 CPUtime=7.59 /proc/26399/stat : 26399 (cupt) R 26398 26399 17872 34816 17872 4202496 12863 7200 0 0 743 9 4 3 20 0 1 0 28335083 73601024 10569 18446744073709551615 4194304 5184042 140734820701168 140734820695416 139737322755515 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26399/statm: 17969 10569 842 242 0 10531 0 Current children cumulated CPU time (s) 7.59 Current children cumulated vsize (KiB) 71876 [startup+7.80312 s] /proc/loadavg: 0.99 0.97 0.81 2/56 26419 /proc/meminfo: memFree=270296/1022884 swapFree=0/0 [pid=26399] ppid=26398 vsize=63420 CPUtime=7.79 /proc/26399/stat : 26399 (cupt) R 26398 26399 17872 34816 17872 4202496 12894 7200 0 0 763 9 4 3 20 0 1 0 28335083 64942080 9281 18446744073709551615 4194304 5184042 140734820701168 140734820700616 139737306402386 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26399/statm: 15855 9281 853 242 0 8417 0 Current children cumulated CPU time (s) 7.79 Current children cumulated vsize (KiB) 63420 Child status: 1 Real time (s): 7.82409 CPU time (s): 7.82049 CPU user time (s): 7.68848 CPU system time (s): 0.132008 CPU usage (%): 99.9539 Max. virtual memory (cumulated for all children) (KiB): 71876 getrusage(RUSAGE_CHILDREN,...) data: user time used= 7.68848 system time used= 0.132008 maximum resident set size= 43184 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 20114 page faults= 0 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 52 involuntary context switches= 141 runsolver used 0.024001 second user time and 0.016001 second system time The end