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/109.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends remove ktuberling libedata-cal5 libattr1 artsbuilder kdemultimedia-kfile-plugins 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 6668 /proc/meminfo: memFree=576452/1022884 swapFree=0/0 [pid=6668] ppid=6667 vsize=3152 CPUtime=0 /proc/6668/stat : 6668 (runsolver) R 6667 17872 17872 34816 17872 4202560 0 0 0 0 0 0 0 0 20 0 1 0 31359824 3227648 32 18446744073709551615 134512640 134586868 4293969024 4293967072 4151919664 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/6668/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.11185 s] /proc/loadavg: 1.00 1.00 1.00 2/55 6668 /proc/meminfo: memFree=576452/1022884 swapFree=0/0 [pid=6668] ppid=6667 vsize=33244 CPUtime=0.13 /proc/6668/stat : 6668 (cupt) R 6667 6668 17872 34816 17872 4202496 1768 7210 0 0 5 2 4 2 20 0 1 0 31359824 34041856 1586 18446744073709551615 4194304 5184042 140735171410944 140735171408136 140421208966896 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6668/statm: 8311 1586 729 242 0 873 0 Current children cumulated CPU time (s) 0.13 Current children cumulated vsize (KiB) 33244 [startup+0.200277 s] /proc/loadavg: 1.00 1.00 1.00 2/55 6668 /proc/meminfo: memFree=576452/1022884 swapFree=0/0 [pid=6668] ppid=6667 vsize=35492 CPUtime=0.21 /proc/6668/stat : 6668 (cupt) R 6667 6668 17872 34816 17872 4202496 2339 7210 0 0 12 3 4 2 20 0 1 0 31359824 36343808 2156 18446744073709551615 4194304 5184042 140735171410944 140735171408136 140421208966896 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6668/statm: 8873 2156 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.00 1.00 1.00 2/55 6668 /proc/meminfo: memFree=576452/1022884 swapFree=0/0 [pid=6668] ppid=6667 vsize=37984 CPUtime=0.31 /proc/6668/stat : 6668 (cupt) R 6667 6668 17872 34816 17872 4202496 3044 7210 0 0 21 4 4 2 20 0 1 0 31359824 38895616 2798 18446744073709551615 4194304 5184042 140735171410944 140735171408136 140421208686779 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6668/statm: 9496 2798 739 242 0 2058 0 Current children cumulated CPU time (s) 0.31 Current children cumulated vsize (KiB) 37984 [startup+0.7002 s] /proc/loadavg: 1.00 1.00 1.00 2/55 6668 /proc/meminfo: memFree=576452/1022884 swapFree=0/0 [pid=6668] ppid=6667 vsize=65500 CPUtime=0.71 /proc/6668/stat : 6668 (cupt) R 6667 6668 17872 34816 17872 4202496 10047 7210 0 0 57 8 4 2 20 0 1 0 31359824 67072000 9792 18446744073709551615 4194304 5184042 140735171410944 140735171408152 140421224931604 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6668/statm: 16375 9792 851 242 0 8937 0 Current children cumulated CPU time (s) 0.71 Current children cumulated vsize (KiB) 65500 [startup+1.5002 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6688 /proc/meminfo: memFree=539864/1022884 swapFree=0/0 [pid=6668] ppid=6667 vsize=67108 CPUtime=1.5 /proc/6668/stat : 6668 (cupt) R 6667 6668 17872 34816 17872 4202496 10553 7210 0 0 136 8 4 2 20 0 1 0 31359824 68718592 10104 18446744073709551615 4194304 5184042 140735171410944 140735171408248 140421208621413 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6668/statm: 16777 10104 851 242 0 9339 0 Current children cumulated CPU time (s) 1.5 Current children cumulated vsize (KiB) 67108 [startup+3.10021 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6688 /proc/meminfo: memFree=538500/1022884 swapFree=0/0 [pid=6668] ppid=6667 vsize=68132 CPUtime=3.1 /proc/6668/stat : 6668 (cupt) R 6667 6668 17872 34816 17872 4202496 10962 7210 0 0 296 8 4 2 20 0 1 0 31359824 69767168 10256 18446744073709551615 4194304 5184042 140735171410944 140735171408376 140421224966213 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6668/statm: 17033 10256 851 242 0 9595 0 Current children cumulated CPU time (s) 3.1 Current children cumulated vsize (KiB) 68132 [startup+6.30021 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6688 /proc/meminfo: memFree=537508/1022884 swapFree=0/0 [pid=6668] ppid=6667 vsize=70768 CPUtime=6.29 /proc/6668/stat : 6668 (cupt) R 6667 6668 17872 34816 17872 4202496 11858 7210 0 0 614 9 4 2 20 0 1 0 31359824 72466432 10639 18446744073709551615 4194304 5184042 140735171410944 140735171408376 140421225139097 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6668/statm: 17692 10639 851 242 0 10254 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 70768 [startup+12.7002 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6688 /proc/meminfo: memFree=535400/1022884 swapFree=0/0 [pid=6668] ppid=6667 vsize=75008 CPUtime=12.66 /proc/6668/stat : 6668 (cupt) R 6667 6668 17872 34816 17872 4202496 13386 7210 0 0 1249 11 4 2 20 0 1 0 31359824 76808192 11142 18446744073709551615 4194304 5184042 140735171410944 140735171408376 140421224965664 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6668/statm: 18752 11142 851 242 0 11314 0 Current children cumulated CPU time (s) 12.66 Current children cumulated vsize (KiB) 75008 [startup+25.5002 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6688 /proc/meminfo: memFree=530936/1022884 swapFree=0/0 [pid=6668] ppid=6667 vsize=75304 CPUtime=25.41 /proc/6668/stat : 6668 (cupt) R 6667 6668 17872 34816 17872 4202496 14447 7210 0 0 2524 11 4 2 20 0 1 0 31359824 77111296 12203 18446744073709551615 4194304 5184042 140735171410944 140735171408248 140421217035264 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6668/statm: 18826 12203 851 242 0 11388 0 Current children cumulated CPU time (s) 25.41 Current children cumulated vsize (KiB) 75304 Solver just ended. Dumping a history of the last processes samples [startup+25.6003 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6688 /proc/meminfo: memFree=530936/1022884 swapFree=0/0 [pid=6668] ppid=6667 vsize=75304 CPUtime=25.51 /proc/6668/stat : 6668 (cupt) R 6667 6668 17872 34816 17872 4202496 14455 7210 0 0 2534 11 4 2 20 0 1 0 31359824 77111296 12211 18446744073709551615 4194304 5184042 140735171410944 140735171408248 140421224981312 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6668/statm: 18826 12211 851 242 0 11388 0 Current children cumulated CPU time (s) 25.51 Current children cumulated vsize (KiB) 75304 [startup+32.0031 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6688 /proc/meminfo: memFree=528952/1022884 swapFree=0/0 [pid=6668] ppid=6667 vsize=83640 CPUtime=31.89 /proc/6668/stat : 6668 (cupt) R 6667 6668 17872 34816 17872 4202496 17004 7210 0 0 3170 13 4 2 20 0 1 0 31359824 85647360 12711 18446744073709551615 4194304 5184042 140735171410944 140735171408248 140421225049292 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6668/statm: 20910 12711 851 242 0 13472 0 Current children cumulated CPU time (s) 31.89 Current children cumulated vsize (KiB) 83640 [startup+38.4002 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6688 /proc/meminfo: memFree=527216/1022884 swapFree=0/0 [pid=6668] ppid=6667 vsize=83640 CPUtime=38.26 /proc/6668/stat : 6668 (cupt) R 6667 6668 17872 34816 17872 4202496 17483 7210 0 0 3806 14 4 2 20 0 1 0 31359824 85647360 13190 18446744073709551615 4194304 5184042 140735171410944 140735171408248 140421224965120 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6668/statm: 20910 13190 851 242 0 13472 0 Current children cumulated CPU time (s) 38.26 Current children cumulated vsize (KiB) 83640 [startup+41.6002 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6688 /proc/meminfo: memFree=525976/1022884 swapFree=0/0 [pid=6668] ppid=6667 vsize=83640 CPUtime=41.45 /proc/6668/stat : 6668 (cupt) R 6667 6668 17872 34816 17872 4202496 17744 7210 0 0 4125 14 4 2 20 0 1 0 31359824 85647360 13451 18446744073709551615 4194304 5184042 140735171410944 140735171408248 140421217430507 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6668/statm: 20910 13451 851 242 0 13472 0 Current children cumulated CPU time (s) 41.45 Current children cumulated vsize (KiB) 83640 [startup+42.4002 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6688 /proc/meminfo: memFree=525604/1022884 swapFree=0/0 [pid=6668] ppid=6667 vsize=83640 CPUtime=42.24 /proc/6668/stat : 6668 (cupt) R 6667 6668 17872 34816 17872 4202496 17804 7210 0 0 4204 14 4 2 20 0 1 0 31359824 85647360 13511 18446744073709551615 4194304 5184042 140735171410944 140735171408248 140421224965675 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6668/statm: 20910 13511 851 242 0 13472 0 Current children cumulated CPU time (s) 42.24 Current children cumulated vsize (KiB) 83640 [startup+43.2002 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6688 /proc/meminfo: memFree=525232/1022884 swapFree=0/0 [pid=6668] ppid=6667 vsize=83640 CPUtime=43.04 /proc/6668/stat : 6668 (cupt) R 6667 6668 17872 34816 17872 4202496 17916 7210 0 0 4284 14 4 2 20 0 1 0 31359824 85647360 13623 18446744073709551615 4194304 5184042 140735171410944 140735171408248 140421225049095 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6668/statm: 20910 13623 851 242 0 13472 0 Current children cumulated CPU time (s) 43.04 Current children cumulated vsize (KiB) 83640 [startup+43.4002 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6688 /proc/meminfo: memFree=525232/1022884 swapFree=0/0 [pid=6668] ppid=6667 vsize=83640 CPUtime=43.23 /proc/6668/stat : 6668 (cupt) R 6667 6668 17872 34816 17872 4202496 17964 7210 0 0 4303 14 4 2 20 0 1 0 31359824 85647360 13671 18446744073709551615 4194304 5184042 140735171410944 140735171408248 140421209353534 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6668/statm: 20910 13671 851 242 0 13472 0 Current children cumulated CPU time (s) 43.23 Current children cumulated vsize (KiB) 83640 [startup+43.5002 s] /proc/loadavg: 1.00 1.00 1.00 2/56 6688 /proc/meminfo: memFree=525232/1022884 swapFree=0/0 [pid=6668] ppid=6667 vsize=83640 CPUtime=43.33 /proc/6668/stat : 6668 (cupt) R 6667 6668 17872 34816 17872 4202496 17976 7210 0 0 4313 14 4 2 20 0 1 0 31359824 85647360 13683 18446744073709551615 4194304 5184042 140735171410944 140735171405240 140421217054050 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/6668/statm: 20910 13683 851 242 0 13472 0 Current children cumulated CPU time (s) 43.33 Current children cumulated vsize (KiB) 83640 Child status: 1 Real time (s): 43.5922 CPU time (s): 43.4467 CPU user time (s): 43.2627 CPU system time (s): 0.184011 CPU usage (%): 99.6663 Max. virtual memory (cumulated for all children) (KiB): 83640 getrusage(RUSAGE_CHILDREN,...) data: user time used= 43.2627 system time used= 0.184011 maximum resident set size= 57164 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 25221 page faults= 0 swaps= 0 block input operations= 0 block output operations= 40 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 52 involuntary context switches= 672 runsolver used 0.068004 second user time and 0.116007 second system time The end