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/54.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends install gtk2-engines-industrial scripts4ticker heroes-sound-tracks xfonts-intl-chinese-big ksimus-boolean 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.02 1.01 0.98 2/55 4255 /proc/meminfo: memFree=582228/1022884 swapFree=0/0 [pid=4255] ppid=4254 vsize=3152 CPUtime=0 /proc/4255/stat : 4255 (runsolver) R 4254 17872 17872 34816 17872 4202560 0 0 0 0 0 0 0 0 20 0 1 0 30552347 3227648 33 18446744073709551615 134512640 134586868 4291395616 4291393664 4151895088 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/4255/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.172466 s] /proc/loadavg: 1.02 1.01 0.98 2/55 4255 /proc/meminfo: memFree=582228/1022884 swapFree=0/0 [pid=4255] ppid=4254 vsize=34832 CPUtime=0.19 /proc/4255/stat : 4255 (cupt) R 4254 4255 17872 34816 17872 4202496 2172 7199 0 0 10 2 5 2 20 0 1 0 30552347 35667968 1990 18446744073709551615 4194304 5184042 140735906782448 140735906779640 139962919595556 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4255/statm: 8708 1990 729 242 0 1270 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 34832 [startup+0.200285 s] /proc/loadavg: 1.02 1.01 0.98 2/55 4255 /proc/meminfo: memFree=582228/1022884 swapFree=0/0 [pid=4255] ppid=4254 vsize=35492 CPUtime=0.22 /proc/4255/stat : 4255 (cupt) R 4254 4255 17872 34816 17872 4202496 2343 7199 0 0 12 3 5 2 20 0 1 0 30552347 36343808 2161 18446744073709551615 4194304 5184042 140735906782448 140735906779640 139962919620946 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4255/statm: 8873 2161 729 242 0 1435 0 Current children cumulated CPU time (s) 0.22 Current children cumulated vsize (KiB) 35492 [startup+0.300261 s] /proc/loadavg: 1.02 1.01 0.98 2/55 4255 /proc/meminfo: memFree=582228/1022884 swapFree=0/0 [pid=4255] ppid=4254 vsize=37984 CPUtime=0.32 /proc/4255/stat : 4255 (cupt) R 4254 4255 17872 34816 17872 4202496 3047 7199 0 0 20 5 5 2 20 0 1 0 30552347 38895616 2802 18446744073709551615 4194304 5184042 140735906782448 140735906779640 139962919555442 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4255/statm: 9496 2802 739 242 0 2058 0 Current children cumulated CPU time (s) 0.32 Current children cumulated vsize (KiB) 37984 [startup+0.7002 s] /proc/loadavg: 1.02 1.01 0.98 2/55 4255 /proc/meminfo: memFree=582228/1022884 swapFree=0/0 [pid=4255] ppid=4254 vsize=65896 CPUtime=0.72 /proc/4255/stat : 4255 (cupt) R 4254 4255 17872 34816 17872 4202496 10109 7199 0 0 54 11 5 2 20 0 1 0 30552347 67477504 9855 18446744073709551615 4194304 5184042 140735906782448 140735906779688 139962927967152 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4255/statm: 16474 9855 851 242 0 9036 0 Current children cumulated CPU time (s) 0.72 Current children cumulated vsize (KiB) 65896 [startup+1.5002 s] /proc/loadavg: 1.02 1.01 0.98 2/56 4275 /proc/meminfo: memFree=544780/1022884 swapFree=0/0 [pid=4255] ppid=4254 vsize=68276 CPUtime=1.51 /proc/4255/stat : 4255 (cupt) R 4254 4255 17872 34816 17872 4202496 10974 7199 0 0 133 11 5 2 20 0 1 0 30552347 69914624 10269 18446744073709551615 4194304 5184042 140735906782448 140735906779896 139962935911840 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4255/statm: 17069 10269 851 242 0 9631 0 Current children cumulated CPU time (s) 1.51 Current children cumulated vsize (KiB) 68276 [startup+3.10021 s] /proc/loadavg: 1.02 1.01 0.98 2/56 4275 /proc/meminfo: memFree=543044/1022884 swapFree=0/0 [pid=4255] ppid=4254 vsize=70472 CPUtime=3.11 /proc/4255/stat : 4255 (cupt) R 4254 4255 17872 34816 17872 4202496 11961 7199 0 0 292 12 5 2 20 0 1 0 30552347 72163328 10743 18446744073709551615 4194304 5184042 140735906782448 140735906776744 139962919555370 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4255/statm: 17618 10743 851 242 0 10180 0 Current children cumulated CPU time (s) 3.11 Current children cumulated vsize (KiB) 70472 [startup+6.3002 s] /proc/loadavg: 1.02 1.01 0.98 2/56 4275 /proc/meminfo: memFree=541804/1022884 swapFree=0/0 [pid=4255] ppid=4254 vsize=74568 CPUtime=6.29 /proc/4255/stat : 4255 (cupt) R 4254 4255 17872 34816 17872 4202496 13279 7199 0 0 610 12 5 2 20 0 1 0 30552347 76357632 11036 18446744073709551615 4194304 5184042 140735906782448 140735906779880 139962935899552 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4255/statm: 18642 11036 851 242 0 11204 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 74568 [startup+12.7002 s] /proc/loadavg: 1.02 1.01 0.98 2/56 4275 /proc/meminfo: memFree=539200/1022884 swapFree=0/0 [pid=4255] ppid=4254 vsize=74568 CPUtime=12.67 /proc/4255/stat : 4255 (cupt) R 4254 4255 17872 34816 17872 4202496 13866 7199 0 0 1247 13 5 2 20 0 1 0 30552347 76357632 11623 18446744073709551615 4194304 5184042 140735906782448 140735906779880 139962935899696 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4255/statm: 18642 11623 851 242 0 11204 0 Current children cumulated CPU time (s) 12.67 Current children cumulated vsize (KiB) 74568 [startup+25.5002 s] /proc/loadavg: 1.02 1.01 0.98 2/56 4275 /proc/meminfo: memFree=534364/1022884 swapFree=0/0 [pid=4255] ppid=4254 vsize=82760 CPUtime=25.42 /proc/4255/stat : 4255 (cupt) R 4254 4255 17872 34816 17872 4202496 17088 7199 0 0 2519 16 5 2 20 0 1 0 30552347 84746240 12796 18446744073709551615 4194304 5184042 140735906782448 140735906779880 139962927989852 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4255/statm: 20690 12796 851 242 0 13252 0 Current children cumulated CPU time (s) 25.42 Current children cumulated vsize (KiB) 82760 [startup+51.1002 s] /proc/loadavg: 1.01 1.00 0.98 2/56 4275 /proc/meminfo: memFree=524692/1022884 swapFree=0/0 [pid=4255] ppid=4254 vsize=99144 CPUtime=50.91 /proc/4255/stat : 4255 (cupt) R 4254 4255 17872 34816 17872 4202496 23640 7199 0 0 5065 19 5 2 20 0 1 0 30552347 101523456 15251 18446744073709551615 4194304 5184042 140735906782448 140735906779880 139962935899786 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4255/statm: 24786 15251 851 242 0 17348 0 Current children cumulated CPU time (s) 50.91 Current children cumulated vsize (KiB) 99144 Solver just ended. Dumping a history of the last processes samples [startup+51.2003 s] /proc/loadavg: 1.01 1.00 0.98 2/56 4275 /proc/meminfo: memFree=524692/1022884 swapFree=0/0 [pid=4255] ppid=4254 vsize=99144 CPUtime=51.01 /proc/4255/stat : 4255 (cupt) R 4254 4255 17872 34816 17872 4202496 23649 7199 0 0 5075 19 5 2 20 0 1 0 30552347 101523456 15260 18446744073709551615 4194304 5184042 140735906782448 140735906779880 139962935899595 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4255/statm: 24786 15260 851 242 0 17348 0 Current children cumulated CPU time (s) 51.01 Current children cumulated vsize (KiB) 99144 [startup+76.8002 s] /proc/loadavg: 1.00 1.00 0.98 2/56 4275 /proc/meminfo: memFree=514772/1022884 swapFree=0/0 [pid=4255] ppid=4254 vsize=99144 CPUtime=76.51 /proc/4255/stat : 4255 (cupt) R 4254 4255 17872 34816 17872 4202496 26136 7199 0 0 7624 20 5 2 20 0 1 0 30552347 101523456 17747 18446744073709551615 4194304 5184042 140735906782448 140735906779880 139962919565612 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4255/statm: 24786 17747 851 242 0 17348 0 Current children cumulated CPU time (s) 76.51 Current children cumulated vsize (KiB) 99144 [startup+89.6002 s] /proc/loadavg: 1.00 1.00 0.98 2/56 4275 /proc/meminfo: memFree=509564/1022884 swapFree=0/0 [pid=4255] ppid=4254 vsize=131912 CPUtime=89.26 /proc/4255/stat : 4255 (cupt) R 4254 4255 17872 34816 17872 4202496 35575 7199 0 0 8893 26 5 2 20 0 1 0 30552347 135077888 18993 18446744073709551615 4194304 5184042 140735906782448 140735906779880 139962935957107 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4255/statm: 32978 18993 851 242 0 25540 0 Current children cumulated CPU time (s) 89.26 Current children cumulated vsize (KiB) 131912 [startup+96.0002 s] /proc/loadavg: 1.00 1.00 0.98 2/56 4275 /proc/meminfo: memFree=506836/1022884 swapFree=0/0 [pid=4255] ppid=4254 vsize=131912 CPUtime=95.63 /proc/4255/stat : 4255 (cupt) R 4254 4255 17872 34816 17872 4202496 36216 7199 0 0 9530 26 5 2 20 0 1 0 30552347 135077888 19634 18446744073709551615 4194304 5184042 140735906782448 140735906779880 139962935899671 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4255/statm: 32978 19634 851 242 0 25540 0 Current children cumulated CPU time (s) 95.63 Current children cumulated vsize (KiB) 131912 [startup+99.2002 s] /proc/loadavg: 1.00 1.00 0.98 2/56 4275 /proc/meminfo: memFree=505596/1022884 swapFree=0/0 [pid=4255] ppid=4254 vsize=131912 CPUtime=98.82 /proc/4255/stat : 4255 (cupt) R 4254 4255 17872 34816 17872 4202496 36519 7199 0 0 9848 27 5 2 20 0 1 0 30552347 135077888 19937 18446744073709551615 4194304 5184042 140735906782448 140735906779880 139962935865578 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4255/statm: 32978 19937 851 242 0 25540 0 Current children cumulated CPU time (s) 98.82 Current children cumulated vsize (KiB) 131912 [startup+100 s] /proc/loadavg: 1.00 1.00 0.98 2/56 4275 /proc/meminfo: memFree=505596/1022884 swapFree=0/0 [pid=4255] ppid=4254 vsize=131912 CPUtime=99.62 /proc/4255/stat : 4255 (cupt) R 4254 4255 17872 34816 17872 4202496 36739 7199 0 0 9927 28 5 2 20 0 1 0 30552347 135077888 20157 18446744073709551615 4194304 5184042 140735906782448 140735906779880 139962935874069 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4255/statm: 32978 20157 851 242 0 25540 0 Current children cumulated CPU time (s) 99.62 Current children cumulated vsize (KiB) 131912 [startup+100.8 s] /proc/loadavg: 1.00 1.00 0.98 2/56 4275 /proc/meminfo: memFree=504604/1022884 swapFree=0/0 [pid=4255] ppid=4254 vsize=131912 CPUtime=100.42 /proc/4255/stat : 4255 (cupt) R 4254 4255 17872 34816 17872 4202496 36953 7199 0 0 10007 28 5 2 20 0 1 0 30552347 135077888 20371 18446744073709551615 4194304 5184042 140735906782448 140735906776744 139962935899860 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4255/statm: 32978 20371 851 242 0 25540 0 Current children cumulated CPU time (s) 100.42 Current children cumulated vsize (KiB) 131912 [startup+101.2 s] /proc/loadavg: 1.00 1.00 0.98 2/56 4275 /proc/meminfo: memFree=503612/1022884 swapFree=0/0 [pid=4255] ppid=4254 vsize=131912 CPUtime=100.82 /proc/4255/stat : 4255 (cupt) R 4254 4255 17872 34816 17872 4202496 37006 7199 0 0 10047 28 5 2 20 0 1 0 30552347 135077888 20424 18446744073709551615 4194304 5184042 140735906782448 140735906776744 139962928368193 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4255/statm: 32978 20424 851 242 0 25540 0 Current children cumulated CPU time (s) 100.82 Current children cumulated vsize (KiB) 131912 Child status: 1 Real time (s): 101.275 CPU time (s): 100.898 CPU user time (s): 100.586 CPU system time (s): 0.312019 CPU usage (%): 99.6284 Max. virtual memory (cumulated for all children) (KiB): 164684 getrusage(RUSAGE_CHILDREN,...) data: user time used= 100.586 system time used= 0.312019 maximum resident set size= 105536 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 44238 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= 1525 runsolver used 0.112007 second user time and 0.300018 second system time The end