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/157.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends remove gtk2-engines-redmond95 kapptemplate libhtml-parser-perl kdemultimedia-kfile-plugins wget 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 Current StackSize limit: 8192 KiB [startup+0 s] /proc/loadavg: 0.93 0.97 0.91 2/55 29352 /proc/meminfo: memFree=311568/1022884 swapFree=0/0 [pid=29352] ppid=29351 vsize=30148 CPUtime=0 /proc/29352/stat : 29352 (cupt) R 29351 29352 17872 34816 17872 4202496 791 0 0 0 0 0 0 0 20 0 1 0 28669451 30871552 690 18446744073709551615 4194304 5184042 140734599027088 140734599025096 139723534892596 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29352/statm: 7537 690 597 242 0 99 0 [startup+0.146625 s] /proc/loadavg: 0.93 0.97 0.91 2/55 29352 /proc/meminfo: memFree=311568/1022884 swapFree=0/0 [pid=29352] ppid=29351 vsize=34168 CPUtime=0.17 /proc/29352/stat : 29352 (cupt) R 29351 29352 17872 34816 17872 4202496 2002 7206 0 0 8 2 4 3 20 0 1 0 28669451 34988032 1820 18446744073709551615 4194304 5184042 140734599027088 140734599024280 139723534929431 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29352/statm: 8542 1820 729 242 0 1104 0 Current children cumulated CPU time (s) 0.17 Current children cumulated vsize (KiB) 34168 [startup+0.200272 s] /proc/loadavg: 0.93 0.97 0.91 2/55 29352 /proc/meminfo: memFree=311568/1022884 swapFree=0/0 [pid=29352] ppid=29351 vsize=35360 CPUtime=0.22 /proc/29352/stat : 29352 (cupt) R 29351 29352 17872 34816 17872 4202496 2319 7206 0 0 12 3 4 3 20 0 1 0 28669451 36208640 2136 18446744073709551615 4194304 5184042 140734599027088 140734599024280 139723551386040 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29352/statm: 8840 2136 729 242 0 1402 0 Current children cumulated CPU time (s) 0.22 Current children cumulated vsize (KiB) 35360 [startup+0.300262 s] /proc/loadavg: 0.93 0.97 0.91 2/55 29352 /proc/meminfo: memFree=311568/1022884 swapFree=0/0 [pid=29352] ppid=29351 vsize=46976 CPUtime=0.31 /proc/29352/stat : 29352 (cupt) R 29351 29352 17872 34816 17872 4202496 5322 7206 0 0 18 6 4 3 20 0 1 0 28669451 48103424 5131 18446744073709551615 4194304 5184042 140734599027088 140734599021576 139723534892596 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29352/statm: 11744 5131 835 242 0 4306 0 Current children cumulated CPU time (s) 0.31 Current children cumulated vsize (KiB) 46976 [startup+0.7002 s] /proc/loadavg: 0.93 0.97 0.91 2/55 29352 /proc/meminfo: memFree=311568/1022884 swapFree=0/0 [pid=29352] ppid=29351 vsize=58604 CPUtime=0.72 /proc/29352/stat : 29352 (cupt) R 29351 29352 17872 34816 17872 4202496 8275 7206 0 0 58 7 4 3 20 0 1 0 28669451 60010496 8027 18446744073709551615 4194304 5184042 140734599027088 140734599024392 139723534889636 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29352/statm: 14651 8027 842 242 0 7213 0 Current children cumulated CPU time (s) 0.72 Current children cumulated vsize (KiB) 58604 [startup+1.50021 s] /proc/loadavg: 0.93 0.97 0.91 2/56 29372 /proc/meminfo: memFree=280940/1022884 swapFree=0/0 [pid=29352] ppid=29351 vsize=61152 CPUtime=1.51 /proc/29352/stat : 29352 (cupt) R 29351 29352 17872 34816 17872 4202496 9061 7206 0 0 137 7 4 3 20 0 1 0 28669451 62619648 8619 18446744073709551615 4194304 5184042 140734599027088 140734599024392 139723551250035 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29352/statm: 15288 8619 842 242 0 7850 0 Current children cumulated CPU time (s) 1.51 Current children cumulated vsize (KiB) 61152 [startup+3.10022 s] /proc/loadavg: 0.93 0.97 0.91 2/56 29372 /proc/meminfo: memFree=276476/1022884 swapFree=0/0 [pid=29352] ppid=29351 vsize=69020 CPUtime=3.11 /proc/29352/stat : 29352 (cupt) R 29351 29352 17872 34816 17872 4202496 11367 7206 0 0 297 7 4 3 20 0 1 0 28669451 70676480 10155 18446744073709551615 4194304 5184042 140734599027088 140734599024536 139723551233748 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29352/statm: 17255 10155 842 242 0 9817 0 Current children cumulated CPU time (s) 3.11 Current children cumulated vsize (KiB) 69020 [startup+6.30021 s] /proc/loadavg: 0.94 0.97 0.91 2/56 29372 /proc/meminfo: memFree=271392/1022884 swapFree=0/0 [pid=29352] ppid=29351 vsize=70684 CPUtime=6.29 /proc/29352/stat : 29352 (cupt) R 29351 29352 17872 34816 17872 4202496 12141 7206 0 0 614 8 4 3 20 0 1 0 28669451 72380416 10929 18446744073709551615 4194304 5184042 140734599027088 140734599020504 139723551233568 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29352/statm: 17671 10929 842 242 0 10233 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 70684 Solver just ended. Dumping a history of the last processes samples [startup+6.40026 s] /proc/loadavg: 0.94 0.97 0.91 2/56 29372 /proc/meminfo: memFree=271392/1022884 swapFree=0/0 [pid=29352] ppid=29351 vsize=70684 CPUtime=6.39 /proc/29352/stat : 29352 (cupt) R 29351 29352 17872 34816 17872 4202496 12149 7206 0 0 624 8 4 3 20 0 1 0 28669451 72380416 10937 18446744073709551615 4194304 5184042 140734599027088 140734599020504 139723551241928 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29352/statm: 17671 10937 842 242 0 10233 0 Current children cumulated CPU time (s) 6.39 Current children cumulated vsize (KiB) 70684 [startup+9.6002 s] /proc/loadavg: 0.94 0.97 0.91 2/56 29372 /proc/meminfo: memFree=267052/1022884 swapFree=0/0 [pid=29352] ppid=29351 vsize=80708 CPUtime=9.58 /proc/29352/stat : 29352 (cupt) R 29351 29352 17872 34816 17872 4202496 14922 7206 0 0 943 8 4 3 20 0 1 0 28669451 82644992 12685 18446744073709551615 4194304 5184042 140734599027088 140734599024392 139723534891116 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29352/statm: 20177 12685 842 242 0 12739 0 Current children cumulated CPU time (s) 9.58 Current children cumulated vsize (KiB) 80708 [startup+11.2002 s] /proc/loadavg: 0.94 0.97 0.91 2/56 29372 /proc/meminfo: memFree=261968/1022884 swapFree=0/0 [pid=29352] ppid=29351 vsize=82116 CPUtime=11.18 /proc/29352/stat : 29352 (cupt) R 29351 29352 17872 34816 17872 4202496 15435 7206 0 0 1102 9 4 3 20 0 1 0 28669451 84086784 13198 18446744073709551615 4194304 5184042 140734599027088 140734599024392 139723551233024 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29352/statm: 20529 13198 842 242 0 13091 0 Current children cumulated CPU time (s) 11.18 Current children cumulated vsize (KiB) 82116 [startup+12.0002 s] /proc/loadavg: 0.94 0.97 0.91 2/56 29372 /proc/meminfo: memFree=261968/1022884 swapFree=0/0 [pid=29352] ppid=29351 vsize=82116 CPUtime=11.97 /proc/29352/stat : 29352 (cupt) R 29351 29352 17872 34816 17872 4202496 15498 7206 0 0 1181 9 4 3 20 0 1 0 28669451 84086784 13261 18446744073709551615 4194304 5184042 140734599027088 140734599024392 139723551233435 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29352/statm: 20529 13261 842 242 0 13091 0 Current children cumulated CPU time (s) 11.97 Current children cumulated vsize (KiB) 82116 [startup+12.4002 s] /proc/loadavg: 0.94 0.97 0.91 2/56 29372 /proc/meminfo: memFree=261720/1022884 swapFree=0/0 [pid=29352] ppid=29351 vsize=82116 CPUtime=12.36 /proc/29352/stat : 29352 (cupt) R 29351 29352 17872 34816 17872 4202496 15523 7206 0 0 1220 9 4 3 20 0 1 0 28669451 84086784 13286 18446744073709551615 4194304 5184042 140734599027088 140734599024392 139723551316142 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29352/statm: 20529 13286 842 242 0 13091 0 Current children cumulated CPU time (s) 12.36 Current children cumulated vsize (KiB) 82116 [startup+12.6002 s] /proc/loadavg: 0.94 0.97 0.91 2/56 29372 /proc/meminfo: memFree=261720/1022884 swapFree=0/0 [pid=29352] ppid=29351 vsize=73920 CPUtime=12.56 /proc/29352/stat : 29352 (cupt) R 29351 29352 17872 34816 17872 4202496 15544 7206 0 0 1240 9 4 3 20 0 1 0 28669451 75694080 11899 18446744073709551615 4194304 5184042 140734599027088 140734599025464 139723534880338 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29352/statm: 18480 11899 853 242 0 11042 0 Current children cumulated CPU time (s) 12.56 Current children cumulated vsize (KiB) 73920 Child status: 1 Real time (s): 12.6599 CPU time (s): 12.6368 CPU user time (s): 12.4968 CPU system time (s): 0.140008 CPU usage (%): 99.8177 Max. virtual memory (cumulated for all children) (KiB): 82116 getrusage(RUSAGE_CHILDREN,...) data: user time used= 12.4968 system time used= 0.140008 maximum resident set size= 53228 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 22770 page faults= 0 swaps= 0 block input operations= 0 block output operations= 168 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 52 involuntary context switches= 215 runsolver used 0.020001 second user time and 0.040002 second system time The end