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/logs/86.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends install libxi-dev dict-freedict-nld-deu ftdi-eeprom libdmalloc4-dev vdr-plugin-sky 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.99 0.98 0.95 2/55 32114 /proc/meminfo: memFree=339992/1022884 swapFree=0/0 [pid=32114] ppid=32113 vsize=3152 CPUtime=0 /proc/32114/stat : 32114 (runsolver) R 32113 17872 17872 34816 17872 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29201751 3227648 33 18446744073709551615 134512640 134586868 4290435328 4290433376 4151587888 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/32114/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.118524 s] /proc/loadavg: 0.99 0.98 0.95 2/55 32114 /proc/meminfo: memFree=339992/1022884 swapFree=0/0 [pid=32114] ppid=32113 vsize=33376 CPUtime=0.13 /proc/32114/stat : 32114 (cupt) R 32113 32114 17872 34816 17872 4202496 1801 7198 0 0 5 2 4 2 20 0 1 0 29201751 34177024 1620 18446744073709551615 4194304 5184042 140733870464768 140733870461960 140692069590981 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/32114/statm: 8344 1620 729 242 0 906 0 Current children cumulated CPU time (s) 0.13 Current children cumulated vsize (KiB) 33376 [startup+0.200276 s] /proc/loadavg: 0.99 0.98 0.95 2/55 32114 /proc/meminfo: memFree=339992/1022884 swapFree=0/0 [pid=32114] ppid=32113 vsize=35360 CPUtime=0.21 /proc/32114/stat : 32114 (cupt) R 32113 32114 17872 34816 17872 4202496 2319 7198 0 0 12 3 4 2 20 0 1 0 29201751 36208640 2137 18446744073709551615 4194304 5184042 140733870464768 140733870461960 140692068946060 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/32114/statm: 8840 2137 729 242 0 1402 0 Current children cumulated CPU time (s) 0.21 Current children cumulated vsize (KiB) 35360 [startup+0.300264 s] /proc/loadavg: 0.99 0.98 0.95 2/55 32114 /proc/meminfo: memFree=339992/1022884 swapFree=0/0 [pid=32114] ppid=32113 vsize=37984 CPUtime=0.31 /proc/32114/stat : 32114 (cupt) R 32113 32114 17872 34816 17872 4202496 3022 7198 0 0 21 4 4 2 20 0 1 0 29201751 38895616 2777 18446744073709551615 4194304 5184042 140733870464768 140733870461960 140692069226224 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/32114/statm: 9496 2777 739 242 0 2058 0 Current children cumulated CPU time (s) 0.31 Current children cumulated vsize (KiB) 37984 [startup+0.700208 s] /proc/loadavg: 0.99 0.98 0.95 2/55 32114 /proc/meminfo: memFree=339992/1022884 swapFree=0/0 [pid=32114] ppid=32113 vsize=66060 CPUtime=0.7 /proc/32114/stat : 32114 (cupt) R 32113 32114 17872 34816 17872 4202496 10150 7198 0 0 54 10 4 2 20 0 1 0 29201751 67645440 9897 18446744073709551615 4194304 5184042 140733870464768 140733870459064 140692068882079 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/32114/statm: 16515 9897 851 242 0 9077 0 Current children cumulated CPU time (s) 0.7 Current children cumulated vsize (KiB) 66060 [startup+1.50021 s] /proc/loadavg: 0.99 0.98 0.95 2/56 32134 /proc/meminfo: memFree=302916/1022884 swapFree=0/0 [pid=32114] ppid=32113 vsize=67388 CPUtime=1.5 /proc/32114/stat : 32114 (cupt) R 32113 32114 17872 34816 17872 4202496 10638 7198 0 0 134 10 4 2 20 0 1 0 29201751 69005312 10191 18446744073709551615 4194304 5184042 140733870464768 140733870461720 140692085199661 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/32114/statm: 16847 10191 851 242 0 9409 0 Current children cumulated CPU time (s) 1.5 Current children cumulated vsize (KiB) 67388 [startup+3.10022 s] /proc/loadavg: 0.99 0.98 0.95 2/56 32134 /proc/meminfo: memFree=301304/1022884 swapFree=0/0 [pid=32114] ppid=32113 vsize=69644 CPUtime=3.1 /proc/32114/stat : 32114 (cupt) R 32113 32114 17872 34816 17872 4202496 11399 7198 0 0 292 12 4 2 20 0 1 0 29201751 71315456 10695 18446744073709551615 4194304 5184042 140733870464768 140733870462072 140692085224992 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/32114/statm: 17411 10695 851 242 0 9973 0 Current children cumulated CPU time (s) 3.1 Current children cumulated vsize (KiB) 69644 [startup+6.30021 s] /proc/loadavg: 0.99 0.98 0.95 2/56 32134 /proc/meminfo: memFree=296840/1022884 swapFree=0/0 [pid=32114] ppid=32113 vsize=74776 CPUtime=6.28 /proc/32114/stat : 32114 (cupt) R 32113 32114 17872 34816 17872 4202496 12895 7198 0 0 609 13 4 2 20 0 1 0 29201751 76570624 11678 18446744073709551615 4194304 5184042 140733870464768 140733870462072 140692085199291 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/32114/statm: 18694 11678 851 242 0 11256 0 Current children cumulated CPU time (s) 6.28 Current children cumulated vsize (KiB) 74776 [startup+12.7002 s] /proc/loadavg: 0.99 0.98 0.95 2/56 32134 /proc/meminfo: memFree=288036/1022884 swapFree=0/0 [pid=32114] ppid=32113 vsize=85892 CPUtime=12.65 /proc/32114/stat : 32114 (cupt) R 32113 32114 17872 34816 17872 4202496 16175 7198 0 0 1244 15 4 2 20 0 1 0 29201751 87953408 13933 18446744073709551615 4194304 5184042 140733870464768 140733870462072 140692085199299 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/32114/statm: 21473 13933 851 242 0 14035 0 Current children cumulated CPU time (s) 12.65 Current children cumulated vsize (KiB) 85892 Solver just ended. Dumping a history of the last processes samples [startup+12.8003 s] /proc/loadavg: 0.99 0.98 0.95 2/56 32134 /proc/meminfo: memFree=288036/1022884 swapFree=0/0 [pid=32114] ppid=32113 vsize=86028 CPUtime=12.75 /proc/32114/stat : 32114 (cupt) R 32113 32114 17872 34816 17872 4202496 16202 7198 0 0 1254 15 4 2 20 0 1 0 29201751 88092672 13960 18446744073709551615 4194304 5184042 140733870464768 140733870462072 140692085225003 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/32114/statm: 21507 13960 851 242 0 14069 0 Current children cumulated CPU time (s) 12.75 Current children cumulated vsize (KiB) 86028 [startup+16.0002 s] /proc/loadavg: 0.99 0.98 0.95 2/56 32134 /proc/meminfo: memFree=284564/1022884 swapFree=0/0 [pid=32114] ppid=32113 vsize=88828 CPUtime=15.95 /proc/32114/stat : 32114 (cupt) R 32113 32114 17872 34816 17872 4202496 17090 7198 0 0 1573 16 4 2 20 0 1 0 29201751 90959872 14848 18446744073709551615 4194304 5184042 140733870464768 140733870462072 140692077694413 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/32114/statm: 22207 14848 851 242 0 14769 0 Current children cumulated CPU time (s) 15.95 Current children cumulated vsize (KiB) 88828 [startup+17.6002 s] /proc/loadavg: 0.99 0.98 0.95 2/56 32134 /proc/meminfo: memFree=283076/1022884 swapFree=0/0 [pid=32114] ppid=32113 vsize=89252 CPUtime=17.54 /proc/32114/stat : 32114 (cupt) R 32113 32114 17872 34816 17872 4202496 17303 7198 0 0 1732 16 4 2 20 0 1 0 29201751 91394048 15061 18446744073709551615 4194304 5184042 140733870464768 140733870462072 140692085224448 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/32114/statm: 22313 15061 851 242 0 14875 0 Current children cumulated CPU time (s) 17.54 Current children cumulated vsize (KiB) 89252 [startup+18.0002 s] /proc/loadavg: 0.99 0.98 0.95 2/56 32134 /proc/meminfo: memFree=283076/1022884 swapFree=0/0 [pid=32114] ppid=32113 vsize=89252 CPUtime=17.94 /proc/32114/stat : 32114 (cupt) R 32113 32114 17872 34816 17872 4202496 17328 7198 0 0 1772 16 4 2 20 0 1 0 29201751 91394048 15086 18446744073709551615 4194304 5184042 140733870464768 140733870462072 140692085224448 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/32114/statm: 22313 15086 851 242 0 14875 0 Current children cumulated CPU time (s) 17.94 Current children cumulated vsize (KiB) 89252 [startup+18.2002 s] /proc/loadavg: 0.99 0.98 0.95 2/56 32134 /proc/meminfo: memFree=283076/1022884 swapFree=0/0 [pid=32114] ppid=32113 vsize=80548 CPUtime=18.14 /proc/32114/stat : 32114 (cupt) R 32113 32114 17872 34816 17872 4202496 17349 7198 0 0 1792 16 4 2 20 0 1 0 29201751 82481152 13565 18446744073709551615 4194304 5184042 140733870464768 140733870464216 140692068871857 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/32114/statm: 20137 13565 862 242 0 12699 0 Current children cumulated CPU time (s) 18.14 Current children cumulated vsize (KiB) 80548 Child status: 1 Real time (s): 18.2499 CPU time (s): 18.2051 CPU user time (s): 18.0091 CPU system time (s): 0.196012 CPU usage (%): 99.7547 Max. virtual memory (cumulated for all children) (KiB): 89252 getrusage(RUSAGE_CHILDREN,...) data: user time used= 18.0091 system time used= 0.196012 maximum resident set size= 60428 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 24567 page faults= 0 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 52 involuntary context switches= 288 runsolver used 0.020001 second user time and 0.060003 second system time The end