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/158.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends remove libxcursor-dev libapr0 freeglut3 libgstreamer-plugins0.8-0 libsasl2 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.92 0.98 0.99 2/55 8699 /proc/meminfo: memFree=578452/1022884 swapFree=0/0 [pid=8699] ppid=8698 vsize=3152 CPUtime=0 /proc/8699/stat : 8699 (runsolver) R 8698 17872 17872 34816 17872 4202560 0 0 0 0 0 0 0 0 20 0 1 0 32033733 3227648 32 18446744073709551615 134512640 134586868 4288028288 4288026336 4151514160 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/8699/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.113105 s] /proc/loadavg: 0.92 0.98 0.99 2/55 8699 /proc/meminfo: memFree=578452/1022884 swapFree=0/0 [pid=8699] ppid=8698 vsize=33508 CPUtime=0.12 /proc/8699/stat : 8699 (cupt) R 8698 8699 17872 34816 17872 4202496 1855 7209 0 0 5 2 4 1 20 0 1 0 32033733 34312192 1673 18446744073709551615 4194304 5184042 140735138977728 140735138974920 140154420564062 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8699/statm: 8377 1673 729 242 0 939 0 Current children cumulated CPU time (s) 0.12 Current children cumulated vsize (KiB) 33508 [startup+0.200258 s] /proc/loadavg: 0.92 0.98 0.99 2/55 8699 /proc/meminfo: memFree=578452/1022884 swapFree=0/0 [pid=8699] ppid=8698 vsize=35892 CPUtime=0.2 /proc/8699/stat : 8699 (cupt) R 8698 8699 17872 34816 17872 4202496 2458 7209 0 0 13 2 4 1 20 0 1 0 32033733 36753408 2273 18446744073709551615 4194304 5184042 140735138977728 140735138974920 140154420494234 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8699/statm: 8973 2273 739 242 0 1535 0 Current children cumulated CPU time (s) 0.2 Current children cumulated vsize (KiB) 35892 [startup+0.300228 s] /proc/loadavg: 0.92 0.98 0.99 2/55 8699 /proc/meminfo: memFree=578452/1022884 swapFree=0/0 [pid=8699] ppid=8698 vsize=38516 CPUtime=0.31 /proc/8699/stat : 8699 (cupt) R 8698 8699 17872 34816 17872 4202496 3161 7209 0 0 22 4 4 1 20 0 1 0 32033733 39440384 2914 18446744073709551615 4194304 5184042 140735138977728 140735138974920 140154420844272 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8699/statm: 9629 2914 739 242 0 2191 0 Current children cumulated CPU time (s) 0.31 Current children cumulated vsize (KiB) 38516 [startup+0.700183 s] /proc/loadavg: 0.92 0.98 0.99 2/55 8699 /proc/meminfo: memFree=578452/1022884 swapFree=0/0 [pid=8699] ppid=8698 vsize=65100 CPUtime=0.7 /proc/8699/stat : 8699 (cupt) R 8698 8699 17872 34816 17872 4202496 9906 7209 0 0 56 9 4 1 20 0 1 0 32033733 66662400 9651 18446744073709551615 4194304 5184042 140735138977728 140735138975032 140154436842496 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8699/statm: 16275 9651 851 242 0 8837 0 Current children cumulated CPU time (s) 0.7 Current children cumulated vsize (KiB) 65100 [startup+1.50014 s] /proc/loadavg: 0.92 0.98 0.99 2/56 8719 /proc/meminfo: memFree=541988/1022884 swapFree=0/0 [pid=8699] ppid=8698 vsize=66300 CPUtime=1.5 /proc/8699/stat : 8699 (cupt) R 8698 8699 17872 34816 17872 4202496 10408 7209 0 0 136 9 4 1 20 0 1 0 32033733 67891200 9959 18446744073709551615 4194304 5184042 140735138977728 140735138975032 140154436842496 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8699/statm: 16575 9959 851 242 0 9137 0 Current children cumulated CPU time (s) 1.5 Current children cumulated vsize (KiB) 66300 [startup+3.10015 s] /proc/loadavg: 0.92 0.98 0.99 2/56 8719 /proc/meminfo: memFree=541244/1022884 swapFree=0/0 [pid=8699] ppid=8698 vsize=69372 CPUtime=3.1 /proc/8699/stat : 8699 (cupt) R 8698 8699 17872 34816 17872 4202496 11586 7209 0 0 296 9 4 1 20 0 1 0 32033733 71036928 10367 18446744073709551615 4194304 5184042 140735138977728 140735138975176 140154436827898 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8699/statm: 17343 10367 851 242 0 9905 0 Current children cumulated CPU time (s) 3.1 Current children cumulated vsize (KiB) 69372 [startup+6.30014 s] /proc/loadavg: 0.93 0.98 0.99 2/56 8719 /proc/meminfo: memFree=539384/1022884 swapFree=0/0 [pid=8699] ppid=8698 vsize=69372 CPUtime=6.28 /proc/8699/stat : 8699 (cupt) R 8698 8699 17872 34816 17872 4202496 11857 7209 0 0 614 9 4 1 20 0 1 0 32033733 71036928 10638 18446744073709551615 4194304 5184042 140735138977728 140735138972024 140154420498956 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8699/statm: 17343 10638 851 242 0 9905 0 Current children cumulated CPU time (s) 6.28 Current children cumulated vsize (KiB) 69372 [startup+12.7001 s] /proc/loadavg: 0.93 0.98 0.99 2/56 8719 /proc/meminfo: memFree=537276/1022884 swapFree=0/0 [pid=8699] ppid=8698 vsize=73740 CPUtime=12.67 /proc/8699/stat : 8699 (cupt) R 8698 8699 17872 34816 17872 4202496 13384 7209 0 0 1252 10 4 1 20 0 1 0 32033733 75509760 11140 18446744073709551615 4194304 5184042 140735138977728 140735138975032 140154429303788 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8699/statm: 18435 11140 851 242 0 10997 0 Current children cumulated CPU time (s) 12.67 Current children cumulated vsize (KiB) 73740 [startup+25.5001 s] /proc/loadavg: 0.95 0.98 0.99 2/56 8719 /proc/meminfo: memFree=533432/1022884 swapFree=0/0 [pid=8699] ppid=8698 vsize=82224 CPUtime=25.42 /proc/8699/stat : 8699 (cupt) R 8698 8699 17872 34816 17872 4202496 16359 7209 0 0 2526 11 4 1 20 0 1 0 32033733 84197376 12066 18446744073709551615 4194304 5184042 140735138977728 140735138975032 140154436926684 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8699/statm: 20556 12066 851 242 0 13118 0 Current children cumulated CPU time (s) 25.42 Current children cumulated vsize (KiB) 82224 [startup+51.1001 s] /proc/loadavg: 0.96 0.98 0.99 2/56 8719 /proc/meminfo: memFree=526240/1022884 swapFree=0/0 [pid=8699] ppid=8698 vsize=82376 CPUtime=50.94 /proc/8699/stat : 8699 (cupt) R 8698 8699 17872 34816 17872 4202496 18158 7209 0 0 5077 12 4 1 20 0 1 0 32033733 84353024 13865 18446744073709551615 4194304 5184042 140735138977728 140735138975032 140154436842598 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8699/statm: 20594 13865 851 242 0 13156 0 Current children cumulated CPU time (s) 50.94 Current children cumulated vsize (KiB) 82376 [startup+102.3 s] /proc/loadavg: 0.98 0.98 0.99 2/56 8719 /proc/meminfo: memFree=511608/1022884 swapFree=0/0 [pid=8699] ppid=8698 vsize=99196 CPUtime=101.98 /proc/8699/stat : 8699 (cupt) R 8698 8699 17872 34816 17872 4202496 25875 7209 0 0 10179 14 4 1 20 0 1 0 32033733 101576704 17485 18446744073709551615 4194304 5184042 140735138977728 140735138975032 140154436926738 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8699/statm: 24799 17485 851 242 0 17361 0 Current children cumulated CPU time (s) 101.98 Current children cumulated vsize (KiB) 99196 Solver just ended. Dumping a history of the last processes samples [startup+102.403 s] /proc/loadavg: 0.98 0.98 0.99 2/56 8719 /proc/meminfo: memFree=511608/1022884 swapFree=0/0 [pid=8699] ppid=8698 vsize=99196 CPUtime=102.08 /proc/8699/stat : 8699 (cupt) R 8698 8699 17872 34816 17872 4202496 25882 7209 0 0 10189 14 4 1 20 0 1 0 32033733 101576704 17492 18446744073709551615 4194304 5184042 140735138977728 140735138975032 140154420500933 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8699/statm: 24799 17492 851 242 0 17361 0 Current children cumulated CPU time (s) 102.08 Current children cumulated vsize (KiB) 99196 [startup+128 s] /proc/loadavg: 0.99 0.98 0.99 2/56 8719 /proc/meminfo: memFree=504540/1022884 swapFree=0/0 [pid=8699] ppid=8698 vsize=131964 CPUtime=127.6 /proc/8699/stat : 8699 (cupt) R 8698 8699 17872 34816 17872 4202496 35827 7209 0 0 12737 18 4 1 20 0 1 0 32033733 135131136 19244 18446744073709551615 4194304 5184042 140735138977728 140735138975160 140154436843016 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8699/statm: 32991 19244 851 242 0 25553 0 Current children cumulated CPU time (s) 127.6 Current children cumulated vsize (KiB) 131964 [startup+134.4 s] /proc/loadavg: 0.99 0.98 0.99 2/56 8719 /proc/meminfo: memFree=502804/1022884 swapFree=0/0 [pid=8699] ppid=8698 vsize=131964 CPUtime=133.97 /proc/8699/stat : 8699 (cupt) R 8698 8699 17872 34816 17872 4202496 36265 7209 0 0 13374 18 4 1 20 0 1 0 32033733 135131136 19682 18446744073709551615 4194304 5184042 140735138977728 140735138975160 140154436842915 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8699/statm: 32991 19682 851 242 0 25553 0 Current children cumulated CPU time (s) 133.97 Current children cumulated vsize (KiB) 131964 [startup+137.603 s] /proc/loadavg: 0.99 0.98 0.99 2/56 8719 /proc/meminfo: memFree=501812/1022884 swapFree=0/0 [pid=8699] ppid=8698 vsize=131964 CPUtime=137.17 /proc/8699/stat : 8699 (cupt) R 8698 8699 17872 34816 17872 4202496 36482 7209 0 0 13694 18 4 1 20 0 1 0 32033733 135131136 19899 18446744073709551615 4194304 5184042 140735138977728 140735138975160 140154436789370 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8699/statm: 32991 19899 851 242 0 25553 0 Current children cumulated CPU time (s) 137.17 Current children cumulated vsize (KiB) 131964 [startup+139.2 s] /proc/loadavg: 0.99 0.98 0.99 2/56 8719 /proc/meminfo: memFree=501440/1022884 swapFree=0/0 [pid=8699] ppid=8698 vsize=131964 CPUtime=138.76 /proc/8699/stat : 8699 (cupt) R 8698 8699 17872 34816 17872 4202496 36661 7209 0 0 13853 18 4 1 20 0 1 0 32033733 135131136 20078 18446744073709551615 4194304 5184042 140735138977728 140735138975160 140154436827858 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8699/statm: 32991 20078 851 242 0 25553 0 Current children cumulated CPU time (s) 138.76 Current children cumulated vsize (KiB) 131964 [startup+140.8 s] /proc/loadavg: 0.99 0.98 0.99 2/56 8719 /proc/meminfo: memFree=500076/1022884 swapFree=0/0 [pid=8699] ppid=8698 vsize=131964 CPUtime=140.36 /proc/8699/stat : 8699 (cupt) R 8698 8699 17872 34816 17872 4202496 36921 7209 0 0 14012 19 4 1 20 0 1 0 32033733 135131136 20338 18446744073709551615 4194304 5184042 140735138977728 140735138975160 140154436789352 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8699/statm: 32991 20338 851 242 0 25553 0 Current children cumulated CPU time (s) 140.36 Current children cumulated vsize (KiB) 131964 [startup+141.2 s] /proc/loadavg: 0.99 0.98 0.99 2/56 8719 /proc/meminfo: memFree=500076/1022884 swapFree=0/0 [pid=8699] ppid=8698 vsize=131964 CPUtime=140.76 /proc/8699/stat : 8699 (cupt) R 8698 8699 17872 34816 17872 4202496 36977 7209 0 0 14052 19 4 1 20 0 1 0 32033733 135131136 20394 18446744073709551615 4194304 5184042 140735138977728 140735138972024 140154436925663 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8699/statm: 32991 20394 851 242 0 25553 0 Current children cumulated CPU time (s) 140.76 Current children cumulated vsize (KiB) 131964 [startup+141.4 s] /proc/loadavg: 0.99 0.98 0.99 2/56 8719 /proc/meminfo: memFree=500076/1022884 swapFree=0/0 [pid=8699] ppid=8698 vsize=131964 CPUtime=140.96 /proc/8699/stat : 8699 (cupt) R 8698 8699 17872 34816 17872 4202496 36994 7209 0 0 14072 19 4 1 20 0 1 0 32033733 135131136 20411 18446744073709551615 4194304 5184042 140735138977728 140735138972024 140154436851391 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8699/statm: 32991 20411 851 242 0 25553 0 Current children cumulated CPU time (s) 140.96 Current children cumulated vsize (KiB) 131964 [startup+141.5 s] /proc/loadavg: 0.99 0.98 0.99 2/56 8719 /proc/meminfo: memFree=500076/1022884 swapFree=0/0 [pid=8699] ppid=8698 vsize=66784 CPUtime=141.05 /proc/8699/stat : 8699 (cupt) R 8698 8699 17872 34816 17872 4202496 37209 7209 0 0 14080 20 4 1 20 0 1 0 32033733 68386816 10093 18446744073709551615 4194304 5184042 140735138977728 140735138977176 140154437519922 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8699/statm: 16696 10093 862 242 0 9258 0 Current children cumulated CPU time (s) 141.05 Current children cumulated vsize (KiB) 66784 Child status: 1 Real time (s): 141.538 CPU time (s): 141.113 CPU user time (s): 140.877 CPU system time (s): 0.236014 CPU usage (%): 99.6999 Max. virtual memory (cumulated for all children) (KiB): 164736 getrusage(RUSAGE_CHILDREN,...) data: user time used= 140.877 system time used= 0.236014 maximum resident set size= 105588 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 44438 page faults= 0 swaps= 0 block input operations= 0 block output operations= 648 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 52 involuntary context switches= 2086 runsolver used 0.132008 second user time and 0.32402 second system time The end