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/81.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends install tinyca pike7.4-pexts-bzip2 libpam0g xbel-utils pydb 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.98 0.99 0.91 2/55 27443 /proc/meminfo: memFree=306944/1022884 swapFree=0/0 [pid=27443] ppid=27442 vsize=30148 CPUtime=0 /proc/27443/stat : 27443 (cupt) R 27442 27443 17872 34816 17872 4202496 791 0 0 0 0 0 0 0 20 0 1 0 28437669 30871552 689 18446744073709551615 4194304 5184042 140734815543888 140734815541896 139868684637044 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/27443/statm: 7537 689 597 242 0 99 0 [startup+0.176646 s] /proc/loadavg: 0.98 0.99 0.91 2/55 27443 /proc/meminfo: memFree=306944/1022884 swapFree=0/0 [pid=27443] ppid=27442 vsize=34832 CPUtime=0.2 /proc/27443/stat : 27443 (cupt) R 27442 27443 17872 34816 17872 4202496 2182 7203 0 0 10 3 5 2 20 0 1 0 28437669 35667968 1999 18446744073709551615 4194304 5184042 140734815543888 140734815541080 139868668843760 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/27443/statm: 8708 1999 729 242 0 1270 0 Current children cumulated CPU time (s) 0.2 Current children cumulated vsize (KiB) 34832 [startup+0.200275 s] /proc/loadavg: 0.98 0.99 0.91 2/55 27443 /proc/meminfo: memFree=306944/1022884 swapFree=0/0 [pid=27443] ppid=27442 vsize=35360 CPUtime=0.23 /proc/27443/stat : 27443 (cupt) R 27442 27443 17872 34816 17872 4202496 2323 7203 0 0 12 4 5 2 20 0 1 0 28437669 36208640 2140 18446744073709551615 4194304 5184042 140734815543888 140734815541080 139868668563539 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/27443/statm: 8840 2140 729 242 0 1402 0 Current children cumulated CPU time (s) 0.23 Current children cumulated vsize (KiB) 35360 [startup+0.300252 s] /proc/loadavg: 0.98 0.99 0.91 2/55 27443 /proc/meminfo: memFree=306944/1022884 swapFree=0/0 [pid=27443] ppid=27442 vsize=46872 CPUtime=0.33 /proc/27443/stat : 27443 (cupt) R 27442 27443 17872 34816 17872 4202496 5310 7203 0 0 20 6 5 2 20 0 1 0 28437669 47996928 5118 18446744073709551615 4194304 5184042 140734815543888 140734815538376 139868668563683 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/27443/statm: 11718 5118 835 242 0 4280 0 Current children cumulated CPU time (s) 0.33 Current children cumulated vsize (KiB) 46872 [startup+0.700197 s] /proc/loadavg: 0.98 0.99 0.91 2/55 27443 /proc/meminfo: memFree=306944/1022884 swapFree=0/0 [pid=27443] ppid=27442 vsize=58908 CPUtime=0.72 /proc/27443/stat : 27443 (cupt) R 27442 27443 17872 34816 17872 4202496 8474 7203 0 0 59 6 5 2 20 0 1 0 28437669 60321792 8081 18446744073709551615 4194304 5184042 140734815543888 140734815541336 139868685446728 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/27443/statm: 14727 8081 842 242 0 7289 0 Current children cumulated CPU time (s) 0.72 Current children cumulated vsize (KiB) 58908 [startup+1.5002 s] /proc/loadavg: 0.98 0.99 0.91 2/56 27463 /proc/meminfo: memFree=275944/1022884 swapFree=0/0 [pid=27443] ppid=27442 vsize=61064 CPUtime=1.51 /proc/27443/stat : 27443 (cupt) R 27442 27443 17872 34816 17872 4202496 9160 7203 0 0 138 6 5 2 20 0 1 0 28437669 62529536 8638 18446744073709551615 4194304 5184042 140734815543888 140734815541192 139868684788840 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/27443/statm: 15266 8638 842 242 0 7828 0 Current children cumulated CPU time (s) 1.51 Current children cumulated vsize (KiB) 61064 [startup+3.10021 s] /proc/loadavg: 0.98 0.99 0.91 2/56 27463 /proc/meminfo: memFree=269744/1022884 swapFree=0/0 [pid=27443] ppid=27442 vsize=67800 CPUtime=3.11 /proc/27443/stat : 27443 (cupt) R 27442 27443 17872 34816 17872 4202496 11954 7203 0 0 296 8 5 2 20 0 1 0 28437669 69427200 9890 18446744073709551615 4194304 5184042 140734815543888 140734815541192 139868684842395 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/27443/statm: 16950 9890 842 242 0 9512 0 Current children cumulated CPU time (s) 3.11 Current children cumulated vsize (KiB) 67800 [startup+6.30021 s] /proc/loadavg: 0.98 0.99 0.91 2/56 27463 /proc/meminfo: memFree=264536/1022884 swapFree=0/0 [pid=27443] ppid=27442 vsize=73080 CPUtime=6.29 /proc/27443/stat : 27443 (cupt) R 27442 27443 17872 34816 17872 4202496 13648 7203 0 0 613 9 5 2 20 0 1 0 28437669 74833920 11584 18446744073709551615 4194304 5184042 140734815543888 140734815538136 139868684816807 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/27443/statm: 18270 11584 842 242 0 10832 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 73080 Solver just ended. Dumping a history of the last processes samples [startup+6.40027 s] /proc/loadavg: 0.98 0.99 0.91 2/56 27463 /proc/meminfo: memFree=264536/1022884 swapFree=0/0 [pid=27443] ppid=27442 vsize=73080 CPUtime=6.39 /proc/27443/stat : 27443 (cupt) R 27442 27443 17872 34816 17872 4202496 13658 7203 0 0 623 9 5 2 20 0 1 0 28437669 74833920 11594 18446744073709551615 4194304 5184042 140734815543888 140734815538136 139868684842390 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/27443/statm: 18270 11594 842 242 0 10832 0 Current children cumulated CPU time (s) 6.39 Current children cumulated vsize (KiB) 73080 [startup+8.00021 s] /proc/loadavg: 0.98 0.99 0.91 2/56 27463 /proc/meminfo: memFree=263048/1022884 swapFree=0/0 [pid=27443] ppid=27442 vsize=77176 CPUtime=7.98 /proc/27443/stat : 27443 (cupt) R 27442 27443 17872 34816 17872 4202496 14834 7203 0 0 782 9 5 2 20 0 1 0 28437669 79028224 11745 18446744073709551615 4194304 5184042 140734815543888 140734815541320 139868684842539 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/27443/statm: 19294 11745 842 242 0 11856 0 Current children cumulated CPU time (s) 7.98 Current children cumulated vsize (KiB) 77176 [startup+8.80021 s] /proc/loadavg: 0.98 0.99 0.91 2/56 27463 /proc/meminfo: memFree=262924/1022884 swapFree=0/0 [pid=27443] ppid=27442 vsize=77176 CPUtime=8.79 /proc/27443/stat : 27443 (cupt) R 27442 27443 17872 34816 17872 4202496 14921 7203 0 0 862 10 5 2 20 0 1 0 28437669 79028224 11832 18446744073709551615 4194304 5184042 140734815543888 140734815538152 139868668498649 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/27443/statm: 19294 11832 842 242 0 11856 0 Current children cumulated CPU time (s) 8.79 Current children cumulated vsize (KiB) 77176 [startup+9.60021 s] /proc/loadavg: 0.98 0.99 0.91 2/56 27463 /proc/meminfo: memFree=262924/1022884 swapFree=0/0 [pid=27443] ppid=27442 vsize=77176 CPUtime=9.58 /proc/27443/stat : 27443 (cupt) R 27442 27443 17872 34816 17872 4202496 15023 7203 0 0 941 10 5 2 20 0 1 0 28437669 79028224 11934 18446744073709551615 4194304 5184042 140734815543888 140734815538152 139868684842400 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/27443/statm: 19294 11934 842 242 0 11856 0 Current children cumulated CPU time (s) 9.58 Current children cumulated vsize (KiB) 77176 [startup+10.0072 s] /proc/loadavg: 0.98 0.99 0.91 2/56 27463 /proc/meminfo: memFree=262304/1022884 swapFree=0/0 [pid=27443] ppid=27442 vsize=77176 CPUtime=9.99 /proc/27443/stat : 27443 (cupt) R 27442 27443 17872 34816 17872 4202496 15070 7203 0 0 982 10 5 2 20 0 1 0 28437669 79028224 11981 18446744073709551615 4194304 5184042 140734815543888 140734815538152 139868684841984 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/27443/statm: 19294 11981 842 242 0 11856 0 Current children cumulated CPU time (s) 9.99 Current children cumulated vsize (KiB) 77176 [startup+10.1002 s] /proc/loadavg: 0.98 0.99 0.91 2/56 27463 /proc/meminfo: memFree=262304/1022884 swapFree=0/0 [pid=27443] ppid=27442 vsize=77176 CPUtime=10.08 /proc/27443/stat : 27443 (cupt) R 27442 27443 17872 34816 17872 4202496 15080 7203 0 0 991 10 5 2 20 0 1 0 28437669 79028224 11991 18446744073709551615 4194304 5184042 140734815543888 140734815538152 139868668498476 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/27443/statm: 19294 11991 842 242 0 11856 0 Current children cumulated CPU time (s) 10.08 Current children cumulated vsize (KiB) 77176 Child status: 1 Real time (s): 10.196 CPU time (s): 10.1846 CPU user time (s): 10.0526 CPU system time (s): 0.132008 CPU usage (%): 99.8885 Max. virtual memory (cumulated for all children) (KiB): 77176 getrusage(RUSAGE_CHILDREN,...) data: user time used= 10.0526 system time used= 0.132008 maximum resident set size= 50716 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 22316 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= 175 runsolver used 0.020001 second user time and 0.028001 second system time The end