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/51.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends install kdesdk-misc libdb4.1++ libwxgtk2.4 alsa-modules-2.4.27-3-k7 libminc0 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.82 2/55 26549 /proc/meminfo: memFree=308720/1022884 swapFree=0/0 [pid=26549] ppid=26548 vsize=3152 CPUtime=0 /proc/26549/stat : 26549 (runsolver) R 26548 17872 17872 34816 17872 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28345505 3227648 32 18446744073709551615 134512640 134586868 4292630096 4292628144 4151977008 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/26549/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.166559 s] /proc/loadavg: 0.99 0.97 0.82 2/55 26549 /proc/meminfo: memFree=308720/1022884 swapFree=0/0 [pid=26549] ppid=26548 vsize=34700 CPUtime=0.18 /proc/26549/stat : 26549 (cupt) R 26548 26549 17872 34816 17872 4202496 2128 7199 0 0 10 2 4 2 20 0 1 0 28345505 35532800 1945 18446744073709551615 4194304 5184042 140736019323936 140736019321128 140452446506511 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26549/statm: 8675 1945 729 242 0 1237 0 Current children cumulated CPU time (s) 0.18 Current children cumulated vsize (KiB) 34700 [startup+0.200267 s] /proc/loadavg: 0.99 0.97 0.82 2/55 26549 /proc/meminfo: memFree=308720/1022884 swapFree=0/0 [pid=26549] ppid=26548 vsize=35492 CPUtime=0.22 /proc/26549/stat : 26549 (cupt) R 26548 26549 17872 34816 17872 4202496 2327 7199 0 0 14 2 4 2 20 0 1 0 28345505 36343808 2144 18446744073709551615 4194304 5184042 140736019323936 140736019321128 140452462963224 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26549/statm: 8873 2144 729 242 0 1435 0 Current children cumulated CPU time (s) 0.22 Current children cumulated vsize (KiB) 35492 [startup+0.300253 s] /proc/loadavg: 0.99 0.97 0.82 2/55 26549 /proc/meminfo: memFree=308720/1022884 swapFree=0/0 [pid=26549] ppid=26548 vsize=47148 CPUtime=0.31 /proc/26549/stat : 26549 (cupt) R 26548 26549 17872 34816 17872 4202496 5373 7199 0 0 21 4 4 2 20 0 1 0 28345505 48279552 5182 18446744073709551615 4194304 5184042 140736019323936 140736019318424 140452462873194 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26549/statm: 11787 5182 835 242 0 4349 0 Current children cumulated CPU time (s) 0.31 Current children cumulated vsize (KiB) 47148 [startup+0.700195 s] /proc/loadavg: 0.99 0.97 0.82 2/55 26549 /proc/meminfo: memFree=308720/1022884 swapFree=0/0 [pid=26549] ppid=26548 vsize=58124 CPUtime=0.71 /proc/26549/stat : 26549 (cupt) R 26548 26549 17872 34816 17872 4202496 8291 7199 0 0 59 6 4 2 20 0 1 0 28345505 59518976 7933 18446744073709551615 4194304 5184042 140736019323936 140736019321240 140452462795518 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26549/statm: 14531 7933 842 242 0 7093 0 Current children cumulated CPU time (s) 0.71 Current children cumulated vsize (KiB) 58124 [startup+1.5002 s] /proc/loadavg: 0.99 0.97 0.82 2/56 26569 /proc/meminfo: memFree=279960/1022884 swapFree=0/0 [pid=26549] ppid=26548 vsize=59044 CPUtime=1.51 /proc/26549/stat : 26549 (cupt) R 26548 26549 17872 34816 17872 4202496 8650 7199 0 0 139 6 4 2 20 0 1 0 28345505 60461056 8098 18446744073709551615 4194304 5184042 140736019323936 140736019321368 140452462826384 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26549/statm: 14761 8098 842 242 0 7323 0 Current children cumulated CPU time (s) 1.51 Current children cumulated vsize (KiB) 59044 [startup+3.1002 s] /proc/loadavg: 0.99 0.97 0.83 2/56 26569 /proc/meminfo: memFree=278844/1022884 swapFree=0/0 [pid=26549] ppid=26548 vsize=60068 CPUtime=3.1 /proc/26549/stat : 26549 (cupt) R 26548 26549 17872 34816 17872 4202496 9148 7199 0 0 298 6 4 2 20 0 1 0 28345505 61509632 8339 18446744073709551615 4194304 5184042 140736019323936 140736019321368 140452446466485 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26549/statm: 15017 8339 842 242 0 7579 0 Current children cumulated CPU time (s) 3.1 Current children cumulated vsize (KiB) 60068 [startup+6.3002 s] /proc/loadavg: 0.99 0.97 0.83 2/56 26569 /proc/meminfo: memFree=277356/1022884 swapFree=0/0 [pid=26549] ppid=26548 vsize=62116 CPUtime=6.29 /proc/26549/stat : 26549 (cupt) R 26548 26549 17872 34816 17872 4202496 10137 7199 0 0 616 7 4 2 20 0 1 0 28345505 63606784 8815 18446744073709551615 4194304 5184042 140736019323936 140736019321368 140452462819007 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26549/statm: 15529 8815 842 242 0 8091 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 62116 [startup+12.7002 s] /proc/loadavg: 0.99 0.97 0.83 2/56 26569 /proc/meminfo: memFree=262848/1022884 swapFree=0/0 [pid=26549] ppid=26548 vsize=76644 CPUtime=12.66 /proc/26549/stat : 26549 (cupt) R 26548 26549 17872 34816 17872 4202496 14717 7199 0 0 1252 8 4 2 20 0 1 0 28345505 78483456 12370 18446744073709551615 4194304 5184042 140736019323936 140736019321240 140452462791266 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26549/statm: 19161 12370 842 242 0 11723 0 Current children cumulated CPU time (s) 12.66 Current children cumulated vsize (KiB) 76644 [startup+25.5002 s] /proc/loadavg: 0.99 0.97 0.83 2/56 26569 /proc/meminfo: memFree=244372/1022884 swapFree=0/0 [pid=26549] ppid=26548 vsize=97328 CPUtime=25.41 /proc/26549/stat : 26549 (cupt) R 26548 26549 17872 34816 17872 4202496 21278 7199 0 0 2523 12 4 2 20 0 1 0 28345505 99663872 16882 18446744073709551615 4194304 5184042 140736019323936 140736019318232 140452462810208 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26549/statm: 24332 16882 842 242 0 16894 0 Current children cumulated CPU time (s) 25.41 Current children cumulated vsize (KiB) 97328 [startup+51.1002 s] /proc/loadavg: 0.99 0.97 0.83 2/56 26569 /proc/meminfo: memFree=240032/1022884 swapFree=0/0 [pid=26549] ppid=26548 vsize=113712 CPUtime=50.9 /proc/26549/stat : 26549 (cupt) R 26548 26549 17872 34816 17872 4202496 26485 7199 0 0 5070 14 4 2 20 0 1 0 28345505 116441088 17992 18446744073709551615 4194304 5184042 140736019323936 140736019321368 140452462810664 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26549/statm: 28428 17992 842 242 0 20990 0 Current children cumulated CPU time (s) 50.9 Current children cumulated vsize (KiB) 113712 Solver just ended. Dumping a history of the last processes samples [startup+51.2003 s] /proc/loadavg: 0.99 0.97 0.83 2/56 26569 /proc/meminfo: memFree=240032/1022884 swapFree=0/0 [pid=26549] ppid=26548 vsize=113712 CPUtime=51 /proc/26549/stat : 26549 (cupt) R 26548 26549 17872 34816 17872 4202496 26489 7199 0 0 5080 14 4 2 20 0 1 0 28345505 116441088 17996 18446744073709551615 4194304 5184042 140736019323936 140736019321368 140452462833312 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26549/statm: 28428 17996 842 242 0 20990 0 Current children cumulated CPU time (s) 51 Current children cumulated vsize (KiB) 113712 [startup+57.6002 s] /proc/loadavg: 0.99 0.97 0.83 2/56 26569 /proc/meminfo: memFree=238792/1022884 swapFree=0/0 [pid=26549] ppid=26548 vsize=113712 CPUtime=57.37 /proc/26549/stat : 26549 (cupt) R 26548 26549 17872 34816 17872 4202496 26786 7199 0 0 5717 14 4 2 20 0 1 0 28345505 116441088 18293 18446744073709551615 4194304 5184042 140736019323936 140736019318232 140452462810667 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26549/statm: 28428 18293 842 242 0 20990 0 Current children cumulated CPU time (s) 57.37 Current children cumulated vsize (KiB) 113712 [startup+60.8002 s] /proc/loadavg: 0.99 0.97 0.83 2/56 26569 /proc/meminfo: memFree=237924/1022884 swapFree=0/0 [pid=26549] ppid=26548 vsize=113712 CPUtime=60.56 /proc/26549/stat : 26549 (cupt) R 26548 26549 17872 34816 17872 4202496 26986 7199 0 0 6036 14 4 2 20 0 1 0 28345505 116441088 18493 18446744073709551615 4194304 5184042 140736019323936 140736019318232 140452462810744 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26549/statm: 28428 18493 842 242 0 20990 0 Current children cumulated CPU time (s) 60.56 Current children cumulated vsize (KiB) 113712 [startup+64.0002 s] /proc/loadavg: 0.99 0.97 0.83 2/56 26569 /proc/meminfo: memFree=237056/1022884 swapFree=0/0 [pid=26549] ppid=26548 vsize=113712 CPUtime=63.75 /proc/26549/stat : 26549 (cupt) R 26548 26549 17872 34816 17872 4202496 27192 7199 0 0 6354 15 4 2 20 0 1 0 28345505 116441088 18699 18446744073709551615 4194304 5184042 140736019323936 140736019318232 140452462810667 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26549/statm: 28428 18699 842 242 0 20990 0 Current children cumulated CPU time (s) 63.75 Current children cumulated vsize (KiB) 113712 [startup+64.8002 s] /proc/loadavg: 0.99 0.97 0.83 2/56 26569 /proc/meminfo: memFree=237056/1022884 swapFree=0/0 [pid=26549] ppid=26548 vsize=113712 CPUtime=64.55 /proc/26549/stat : 26549 (cupt) R 26548 26549 17872 34816 17872 4202496 27246 7199 0 0 6434 15 4 2 20 0 1 0 28345505 116441088 18753 18446744073709551615 4194304 5184042 140736019323936 140736019318232 140452462784925 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26549/statm: 28428 18753 842 242 0 20990 0 Current children cumulated CPU time (s) 64.55 Current children cumulated vsize (KiB) 113712 [startup+65.6002 s] /proc/loadavg: 0.99 0.97 0.83 2/56 26569 /proc/meminfo: memFree=236932/1022884 swapFree=0/0 [pid=26549] ppid=26548 vsize=113712 CPUtime=65.35 /proc/26549/stat : 26549 (cupt) R 26548 26549 17872 34816 17872 4202496 27298 7199 0 0 6514 15 4 2 20 0 1 0 28345505 116441088 18805 18446744073709551615 4194304 5184042 140736019323936 140736019318232 140452462868128 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26549/statm: 28428 18805 842 242 0 20990 0 Current children cumulated CPU time (s) 65.35 Current children cumulated vsize (KiB) 113712 [startup+65.8002 s] /proc/loadavg: 0.99 0.97 0.83 2/56 26569 /proc/meminfo: memFree=236932/1022884 swapFree=0/0 [pid=26549] ppid=26548 vsize=80680 CPUtime=65.55 /proc/26549/stat : 26549 (cupt) R 26548 26549 17872 34816 17872 4202496 27317 7199 0 0 6533 16 4 2 20 0 1 0 28345505 82616320 13567 18446744073709551615 4194304 5184042 140736019323936 140736019323384 4592300 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26549/statm: 20170 13567 853 242 0 12732 0 Current children cumulated CPU time (s) 65.55 Current children cumulated vsize (KiB) 80680 Child status: 1 Real time (s): 65.8646 CPU time (s): 65.6281 CPU user time (s): 65.4281 CPU system time (s): 0.200012 CPU usage (%): 99.6409 Max. virtual memory (cumulated for all children) (KiB): 130100 getrusage(RUSAGE_CHILDREN,...) data: user time used= 65.4281 system time used= 0.200012 maximum resident set size= 87260 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 34536 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= 995 runsolver used 0 second user time and 0.272017 second system time The end