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/19.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends install gnome-gpg hostap-modules-2.6.8-4-386 rarpd shntool lesstif2 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.91 0.97 0.97 2/55 2765 /proc/meminfo: memFree=539264/1022884 swapFree=0/0 [pid=2765] ppid=2764 vsize=3152 CPUtime=0 /proc/2765/stat : 2765 (runsolver) R 2764 17872 17872 34816 17872 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29999643 3227648 32 18446744073709551615 134512640 134586868 4287485008 4287483056 4152034352 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/2765/statm: 788 32 0 19 0 73 0 [startup+0.189629 s] /proc/loadavg: 0.91 0.97 0.97 2/55 2765 /proc/meminfo: memFree=539264/1022884 swapFree=0/0 [pid=2765] ppid=2764 vsize=35228 CPUtime=0.2 /proc/2765/stat : 2765 (cupt) R 2764 2765 17872 34816 17872 4202496 2277 7195 0 0 12 2 4 2 20 0 1 0 29999643 36073472 2093 18446744073709551615 4194304 5184042 140734387275712 140734387272904 140227319770655 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2765/statm: 8807 2093 729 242 0 1369 0 Current children cumulated CPU time (s) 0.2 Current children cumulated vsize (KiB) 35228 [startup+0.20027 s] /proc/loadavg: 0.91 0.97 0.97 2/55 2765 /proc/meminfo: memFree=539264/1022884 swapFree=0/0 [pid=2765] ppid=2764 vsize=35492 CPUtime=0.22 /proc/2765/stat : 2765 (cupt) R 2764 2765 17872 34816 17872 4202496 2341 7195 0 0 14 2 4 2 20 0 1 0 29999643 36343808 2157 18446744073709551615 4194304 5184042 140734387275712 140734387272904 140227336260627 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2765/statm: 8873 2157 729 242 0 1435 0 Current children cumulated CPU time (s) 0.22 Current children cumulated vsize (KiB) 35492 [startup+0.300252 s] /proc/loadavg: 0.91 0.97 0.97 2/55 2765 /proc/meminfo: memFree=539264/1022884 swapFree=0/0 [pid=2765] ppid=2764 vsize=37984 CPUtime=0.31 /proc/2765/stat : 2765 (cupt) R 2764 2765 17872 34816 17872 4202496 3046 7195 0 0 21 4 4 2 20 0 1 0 29999643 38895616 2799 18446744073709551615 4194304 5184042 140734387275712 140734387272904 140227319664684 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2765/statm: 9496 2799 739 242 0 2058 0 Current children cumulated CPU time (s) 0.31 Current children cumulated vsize (KiB) 37984 [startup+0.700197 s] /proc/loadavg: 0.91 0.97 0.97 2/55 2765 /proc/meminfo: memFree=539264/1022884 swapFree=0/0 [pid=2765] ppid=2764 vsize=64460 CPUtime=0.71 /proc/2765/stat : 2765 (cupt) R 2764 2765 17872 34816 17872 4202496 9769 7195 0 0 55 10 4 2 20 0 1 0 29999643 66007040 9513 18446744073709551615 4194304 5184042 140734387275712 140734387272952 140227336021430 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2765/statm: 16115 9513 851 242 0 8677 0 Current children cumulated CPU time (s) 0.71 Current children cumulated vsize (KiB) 64460 [startup+1.50019 s] /proc/loadavg: 0.91 0.97 0.97 2/56 2785 /proc/meminfo: memFree=503668/1022884 swapFree=0/0 [pid=2765] ppid=2764 vsize=66544 CPUtime=1.5 /proc/2765/stat : 2765 (cupt) R 2764 2765 17872 34816 17872 4202496 10512 7195 0 0 134 10 4 2 20 0 1 0 29999643 68141056 9805 18446744073709551615 4194304 5184042 140734387275712 140734387273016 140227336074336 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2765/statm: 16636 9805 851 242 0 9198 0 Current children cumulated CPU time (s) 1.5 Current children cumulated vsize (KiB) 66544 [startup+3.10021 s] /proc/loadavg: 0.91 0.97 0.97 2/56 2785 /proc/meminfo: memFree=502800/1022884 swapFree=0/0 [pid=2765] ppid=2764 vsize=69128 CPUtime=3.1 /proc/2765/stat : 2765 (cupt) R 2764 2765 17872 34816 17872 4202496 11548 7195 0 0 292 12 4 2 20 0 1 0 29999643 70787072 10328 18446744073709551615 4194304 5184042 140734387275712 140734387273016 140227336074850 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2765/statm: 17282 10328 851 242 0 9844 0 Current children cumulated CPU time (s) 3.1 Current children cumulated vsize (KiB) 69128 [startup+6.30013 s] /proc/loadavg: 0.92 0.97 0.97 2/56 2785 /proc/meminfo: memFree=500072/1022884 swapFree=0/0 [pid=2765] ppid=2764 vsize=73360 CPUtime=6.28 /proc/2765/stat : 2765 (cupt) R 2764 2765 17872 34816 17872 4202496 12998 7195 0 0 610 12 4 2 20 0 1 0 29999643 75120640 10753 18446744073709551615 4194304 5184042 140734387275712 140734387273160 140227336090483 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2765/statm: 18340 10753 851 242 0 10902 0 Current children cumulated CPU time (s) 6.28 Current children cumulated vsize (KiB) 73360 [startup+12.7002 s] /proc/loadavg: 0.93 0.97 0.97 2/56 2785 /proc/meminfo: memFree=496600/1022884 swapFree=0/0 [pid=2765] ppid=2764 vsize=73660 CPUtime=12.66 /proc/2765/stat : 2765 (cupt) R 2764 2765 17872 34816 17872 4202496 13814 7195 0 0 1247 13 4 2 20 0 1 0 29999643 75427840 11569 18446744073709551615 4194304 5184042 140734387275712 140734387273016 140227328251225 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2765/statm: 18415 11569 851 242 0 10977 0 Current children cumulated CPU time (s) 12.66 Current children cumulated vsize (KiB) 73660 [startup+25.5002 s] /proc/loadavg: 1.02 0.99 0.98 2/56 2785 /proc/meminfo: memFree=490152/1022884 swapFree=0/0 [pid=2765] ppid=2764 vsize=82172 CPUtime=25.41 /proc/2765/stat : 2765 (cupt) R 2764 2765 17872 34816 17872 4202496 17405 7195 0 0 2518 17 4 2 20 0 1 0 29999643 84144128 13111 18446744073709551615 4194304 5184042 140734387275712 140734387273016 140227328163166 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2765/statm: 20543 13111 851 242 0 13105 0 Current children cumulated CPU time (s) 25.41 Current children cumulated vsize (KiB) 82172 [startup+51.1002 s] /proc/loadavg: 1.09 1.00 0.98 2/56 2785 /proc/meminfo: memFree=458284/1022884 swapFree=0/0 [pid=2765] ppid=2764 vsize=135252 CPUtime=50.9 /proc/2765/stat : 2765 (cupt) R 2764 2765 17872 34816 17872 4202496 37789 7195 0 0 5054 30 4 2 20 0 1 0 29999643 138498048 21205 18446744073709551615 4194304 5184042 140734387275712 140734387273144 140227336021181 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2765/statm: 33813 21205 851 242 0 26375 0 Current children cumulated CPU time (s) 50.9 Current children cumulated vsize (KiB) 135252 [startup+102.3 s] /proc/loadavg: 1.04 1.00 0.98 2/56 2785 /proc/meminfo: memFree=395292/1022884 swapFree=0/0 [pid=2765] ppid=2764 vsize=201316 CPUtime=101.9 /proc/2765/stat : 2765 (cupt) R 2764 2765 17872 34816 17872 4202496 69686 7195 0 0 10138 46 4 2 20 0 1 0 29999643 206147584 36717 18446744073709551615 4194304 5184042 140734387275712 140734387273016 140227336087671 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2765/statm: 50329 36717 851 242 0 42891 0 Current children cumulated CPU time (s) 101.9 Current children cumulated vsize (KiB) 201316 Solver just ended. Dumping a history of the last processes samples [startup+102.407 s] /proc/loadavg: 1.04 1.00 0.98 2/56 2785 /proc/meminfo: memFree=395292/1022884 swapFree=0/0 [pid=2765] ppid=2764 vsize=201316 CPUtime=102.01 /proc/2765/stat : 2765 (cupt) R 2764 2765 17872 34816 17872 4202496 69715 7195 0 0 10149 46 4 2 20 0 1 0 29999643 206147584 36746 18446744073709551615 4194304 5184042 140734387275712 140734387273016 140227328147024 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2765/statm: 50329 36746 851 242 0 42891 0 Current children cumulated CPU time (s) 102.01 Current children cumulated vsize (KiB) 201316 [startup+128 s] /proc/loadavg: 1.02 1.00 0.98 2/56 2785 /proc/meminfo: memFree=370740/1022884 swapFree=0/0 [pid=2765] ppid=2764 vsize=205764 CPUtime=127.5 /proc/2765/stat : 2765 (cupt) R 2764 2765 17872 34816 17872 4202496 75812 7195 0 0 12690 54 4 2 20 0 1 0 29999643 210702336 42843 18446744073709551615 4194304 5184042 140734387275712 140734387273016 140227335836880 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2765/statm: 51441 42843 851 242 0 44003 0 Current children cumulated CPU time (s) 127.5 Current children cumulated vsize (KiB) 205764 [startup+140.8 s] /proc/loadavg: 1.02 1.00 0.98 2/56 2785 /proc/meminfo: memFree=364416/1022884 swapFree=0/0 [pid=2765] ppid=2764 vsize=206324 CPUtime=140.25 /proc/2765/stat : 2765 (cupt) R 2764 2765 17872 34816 17872 4202496 77392 7195 0 0 13962 57 4 2 20 0 1 0 29999643 211275776 44423 18446744073709551615 4194304 5184042 140734387275712 140734387270008 140227336021424 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2765/statm: 51581 44423 851 242 0 44143 0 Current children cumulated CPU time (s) 140.25 Current children cumulated vsize (KiB) 206324 [startup+144 s] /proc/loadavg: 1.02 1.00 0.98 2/56 2785 /proc/meminfo: memFree=361564/1022884 swapFree=0/0 [pid=2765] ppid=2764 vsize=337396 CPUtime=143.44 /proc/2765/stat : 2765 (cupt) R 2764 2765 17872 34816 17872 4202496 111079 7195 0 0 14270 68 4 2 20 0 1 0 29999643 345493504 45341 18446744073709551615 4194304 5184042 140734387275712 140734387273144 140227336099080 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2765/statm: 84349 45341 851 242 0 76911 0 Current children cumulated CPU time (s) 143.44 Current children cumulated vsize (KiB) 337396 [startup+147.2 s] /proc/loadavg: 1.02 1.00 0.98 2/56 2785 /proc/meminfo: memFree=357472/1022884 swapFree=0/0 [pid=2765] ppid=2764 vsize=339040 CPUtime=146.63 /proc/2765/stat : 2765 (cupt) R 2764 2765 17872 34816 17872 4202496 111887 7195 0 0 14588 69 4 2 20 0 1 0 29999643 347176960 46149 18446744073709551615 4194304 5184042 140734387275712 140734387270008 140227336123728 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2765/statm: 84760 46149 851 242 0 77322 0 Current children cumulated CPU time (s) 146.63 Current children cumulated vsize (KiB) 339040 [startup+148 s] /proc/loadavg: 1.02 1.00 0.98 2/56 2785 /proc/meminfo: memFree=357348/1022884 swapFree=0/0 [pid=2765] ppid=2764 vsize=339040 CPUtime=147.42 /proc/2765/stat : 2765 (cupt) R 2764 2765 17872 34816 17872 4202496 111925 7195 0 0 14667 69 4 2 20 0 1 0 29999643 347176960 46187 18446744073709551615 4194304 5184042 140734387275712 140734387270008 140227319721379 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2765/statm: 84760 46187 851 242 0 77322 0 Current children cumulated CPU time (s) 147.42 Current children cumulated vsize (KiB) 339040 [startup+148.4 s] /proc/loadavg: 1.02 1.00 0.98 2/56 2785 /proc/meminfo: memFree=357348/1022884 swapFree=0/0 [pid=2765] ppid=2764 vsize=340760 CPUtime=147.82 /proc/2765/stat : 2765 (cupt) R 2764 2765 17872 34816 17872 4202496 112380 7195 0 0 14707 69 4 2 20 0 1 0 29999643 348938240 46642 18446744073709551615 4194304 5184042 140734387275712 140734387269128 140227336157024 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2765/statm: 85190 46642 851 242 0 77752 0 Current children cumulated CPU time (s) 147.82 Current children cumulated vsize (KiB) 340760 [startup+148.8 s] /proc/loadavg: 1.02 1.00 0.98 2/56 2785 /proc/meminfo: memFree=355364/1022884 swapFree=0/0 [pid=2765] ppid=2764 vsize=78100 CPUtime=148.22 /proc/2765/stat : 2765 (cupt) R 2764 2765 17872 34816 17872 4202496 112397 7195 0 0 14744 72 4 2 20 0 1 0 29999643 79974400 12929 18446744073709551615 4194304 5184042 140734387275712 140734387275160 140227336719521 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2765/statm: 19525 12929 862 242 0 12087 0 Current children cumulated CPU time (s) 148.22 Current children cumulated vsize (KiB) 78100 Child status: 1 Real time (s): 148.817 CPU time (s): 148.253 CPU user time (s): 147.489 CPU system time (s): 0.764047 CPU usage (%): 99.6209 Max. virtual memory (cumulated for all children) (KiB): 468472 getrusage(RUSAGE_CHILDREN,...) data: user time used= 147.489 system time used= 0.764047 maximum resident set size= 310996 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 119612 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= 2321 runsolver used 0.16401 second user time and 0.432027 second system time The end