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/133.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends remove libogg0 libgsf-1-dev libpcsclite1 kdelibs4 kfilereplace 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.00 0.99 0.91 2/55 28591 /proc/meminfo: memFree=304384/1022884 swapFree=0/0 [pid=28591] ppid=28590 vsize=3152 CPUtime=0 /proc/28591/stat : 28591 (runsolver) R 28590 17872 17872 34816 17872 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28566980 3227648 32 18446744073709551615 134512640 134586868 4290941360 4290939408 4151649328 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/28591/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.142235 s] /proc/loadavg: 1.00 0.99 0.91 2/55 28591 /proc/meminfo: memFree=304384/1022884 swapFree=0/0 [pid=28591] ppid=28590 vsize=34036 CPUtime=0.16 /proc/28591/stat : 28591 (cupt) R 28590 28591 17872 34816 17872 4202496 1977 7205 0 0 7 2 4 3 20 0 1 0 28566980 34852864 1795 18446744073709551615 4194304 5184042 140733801379648 140733801376840 139913954221075 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28591/statm: 8509 1795 729 242 0 1071 0 Current children cumulated CPU time (s) 0.16 Current children cumulated vsize (KiB) 34036 [startup+0.200271 s] /proc/loadavg: 1.00 0.99 0.91 2/55 28591 /proc/meminfo: memFree=304384/1022884 swapFree=0/0 [pid=28591] ppid=28590 vsize=35360 CPUtime=0.22 /proc/28591/stat : 28591 (cupt) R 28590 28591 17872 34816 17872 4202496 2323 7205 0 0 11 4 4 3 20 0 1 0 28566980 36208640 2140 18446744073709551615 4194304 5184042 140733801379648 140733801376840 139913937756272 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28591/statm: 8840 2140 729 242 0 1402 0 Current children cumulated CPU time (s) 0.22 Current children cumulated vsize (KiB) 35360 [startup+0.300254 s] /proc/loadavg: 1.00 0.99 0.91 2/55 28591 /proc/meminfo: memFree=304384/1022884 swapFree=0/0 [pid=28591] ppid=28590 vsize=47108 CPUtime=0.32 /proc/28591/stat : 28591 (cupt) R 28590 28591 17872 34816 17872 4202496 5340 7205 0 0 19 6 4 3 20 0 1 0 28566980 48238592 5149 18446744073709551615 4194304 5184042 140733801379648 140733801375848 139913954092717 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28591/statm: 11777 5149 835 242 0 4339 0 Current children cumulated CPU time (s) 0.32 Current children cumulated vsize (KiB) 47108 [startup+0.700192 s] /proc/loadavg: 1.00 0.99 0.91 2/55 28591 /proc/meminfo: memFree=304384/1022884 swapFree=0/0 [pid=28591] ppid=28590 vsize=58948 CPUtime=0.72 /proc/28591/stat : 28591 (cupt) R 28590 28591 17872 34816 17872 4202496 8358 7205 0 0 57 8 4 3 20 0 1 0 28566980 60362752 8069 18446744073709551615 4194304 5184042 140733801379648 140733801377080 139913954092717 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28591/statm: 14737 8069 842 242 0 7299 0 Current children cumulated CPU time (s) 0.72 Current children cumulated vsize (KiB) 58948 [startup+1.5002 s] /proc/loadavg: 1.00 0.99 0.91 2/56 28611 /proc/meminfo: memFree=273748/1022884 swapFree=0/0 [pid=28591] ppid=28590 vsize=60636 CPUtime=1.51 /proc/28591/stat : 28591 (cupt) R 28590 28591 17872 34816 17872 4202496 8912 7205 0 0 136 8 4 3 20 0 1 0 28566980 62091264 8494 18446744073709551615 4194304 5184042 140733801379648 140733801376952 139913954035232 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28591/statm: 15159 8494 842 242 0 7721 0 Current children cumulated CPU time (s) 1.51 Current children cumulated vsize (KiB) 60636 [startup+3.1002 s] /proc/loadavg: 1.00 0.99 0.91 2/56 28611 /proc/meminfo: memFree=267672/1022884 swapFree=0/0 [pid=28591] ppid=28590 vsize=68924 CPUtime=3.11 /proc/28591/stat : 28591 (cupt) R 28590 28591 17872 34816 17872 4202496 11353 7205 0 0 295 9 4 3 20 0 1 0 28566980 70578176 10165 18446744073709551615 4194304 5184042 140733801379648 140733801373944 139913954035304 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28591/statm: 17231 10165 842 242 0 9793 0 Current children cumulated CPU time (s) 3.11 Current children cumulated vsize (KiB) 68924 [startup+6.3002 s] /proc/loadavg: 1.00 0.99 0.91 2/56 28611 /proc/meminfo: memFree=261100/1022884 swapFree=0/0 [pid=28591] ppid=28590 vsize=73732 CPUtime=6.29 /proc/28591/stat : 28591 (cupt) R 28590 28591 17872 34816 17872 4202496 12867 7205 0 0 612 10 4 3 20 0 1 0 28566980 75501568 11679 18446744073709551615 4194304 5184042 140733801379648 140733801373912 139913954034688 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28591/statm: 18433 11679 842 242 0 10995 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 73732 [startup+12.7002 s] /proc/loadavg: 1.00 0.99 0.91 2/56 28611 /proc/meminfo: memFree=258620/1022884 swapFree=0/0 [pid=28591] ppid=28590 vsize=77828 CPUtime=12.67 /proc/28591/stat : 28591 (cupt) R 28590 28591 17872 34816 17872 4202496 14516 7205 0 0 1249 11 4 3 20 0 1 0 28566980 79695872 12303 18446744073709551615 4194304 5184042 140733801379648 140733801373944 139913954035080 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28591/statm: 19457 12303 842 242 0 12019 0 Current children cumulated CPU time (s) 12.67 Current children cumulated vsize (KiB) 77828 [startup+25.5002 s] /proc/loadavg: 1.00 0.99 0.91 2/56 28611 /proc/meminfo: memFree=253412/1022884 swapFree=0/0 [pid=28591] ppid=28590 vsize=86020 CPUtime=25.42 /proc/28591/stat : 28591 (cupt) R 28590 28591 17872 34816 17872 4202496 17817 7205 0 0 2522 13 4 3 20 0 1 0 28566980 88084480 13555 18446744073709551615 4194304 5184042 140733801379648 140733801377080 139913954015650 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28591/statm: 21505 13555 842 242 0 14067 0 Current children cumulated CPU time (s) 25.42 Current children cumulated vsize (KiB) 86020 Solver just ended. Dumping a history of the last processes samples [startup+25.6003 s] /proc/loadavg: 1.00 0.99 0.91 2/56 28611 /proc/meminfo: memFree=253412/1022884 swapFree=0/0 [pid=28591] ppid=28590 vsize=86020 CPUtime=25.52 /proc/28591/stat : 28591 (cupt) R 28590 28591 17872 34816 17872 4202496 17826 7205 0 0 2532 13 4 3 20 0 1 0 28566980 88084480 13564 18446744073709551615 4194304 5184042 140733801379648 140733801377080 4592261 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28591/statm: 21505 13564 842 242 0 14067 0 Current children cumulated CPU time (s) 25.52 Current children cumulated vsize (KiB) 86020 [startup+32.0031 s] /proc/loadavg: 1.00 0.99 0.91 2/56 28619 /proc/meminfo: memFree=250684/1022884 swapFree=0/0 [pid=28591] ppid=28590 vsize=86020 CPUtime=31.87 /proc/28591/stat : 28591 (cupt) R 28590 28591 17872 34816 17872 4202496 18442 7205 0 0 3167 13 4 3 20 0 1 0 28566980 88084480 14180 18446744073709551615 4194304 5184042 140733801379648 140733801373944 139913954035232 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28591/statm: 21505 14180 842 242 0 14067 0 Current children cumulated CPU time (s) 31.87 Current children cumulated vsize (KiB) 86020 [startup+38.4002 s] /proc/loadavg: 1.00 0.99 0.91 2/56 28619 /proc/meminfo: memFree=248576/1022884 swapFree=0/0 [pid=28591] ppid=28590 vsize=86020 CPUtime=38.25 /proc/28591/stat : 28591 (cupt) R 28590 28591 17872 34816 17872 4202496 19062 7205 0 0 3804 14 4 3 20 0 1 0 28566980 88084480 14800 18446744073709551615 4194304 5184042 140733801379648 140733801373912 139913954035278 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28591/statm: 21505 14800 842 242 0 14067 0 Current children cumulated CPU time (s) 38.25 Current children cumulated vsize (KiB) 86020 [startup+40.0002 s] /proc/loadavg: 1.00 0.99 0.91 2/56 28619 /proc/meminfo: memFree=247336/1022884 swapFree=0/0 [pid=28591] ppid=28590 vsize=102404 CPUtime=39.83 /proc/28591/stat : 28591 (cupt) R 28590 28591 17872 34816 17872 4202496 23311 7205 0 0 3961 15 4 3 20 0 1 0 28566980 104861696 14952 18446744073709551615 4194304 5184042 140733801379648 140733801377080 139913954045856 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28591/statm: 25601 14952 842 242 0 18163 0 Current children cumulated CPU time (s) 39.83 Current children cumulated vsize (KiB) 102404 [startup+41.6002 s] /proc/loadavg: 1.00 0.99 0.91 2/56 28619 /proc/meminfo: memFree=247336/1022884 swapFree=0/0 [pid=28591] ppid=28590 vsize=102404 CPUtime=41.44 /proc/28591/stat : 28591 (cupt) R 28590 28591 17872 34816 17872 4202496 23465 7205 0 0 4121 16 4 3 20 0 1 0 28566980 104861696 15106 18446744073709551615 4194304 5184042 140733801379648 140733801377080 139913954035298 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28591/statm: 25601 15106 842 242 0 18163 0 Current children cumulated CPU time (s) 41.44 Current children cumulated vsize (KiB) 102404 [startup+42.0002 s] /proc/loadavg: 1.00 0.99 0.91 2/56 28619 /proc/meminfo: memFree=246964/1022884 swapFree=0/0 [pid=28591] ppid=28590 vsize=102404 CPUtime=41.83 /proc/28591/stat : 28591 (cupt) R 28590 28591 17872 34816 17872 4202496 23504 7205 0 0 4160 16 4 3 20 0 1 0 28566980 104861696 15145 18446744073709551615 4194304 5184042 140733801379648 140733801377080 139913937693125 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28591/statm: 25601 15145 842 242 0 18163 0 Current children cumulated CPU time (s) 41.83 Current children cumulated vsize (KiB) 102404 [startup+42.4002 s] /proc/loadavg: 1.00 0.99 0.91 2/56 28619 /proc/meminfo: memFree=246964/1022884 swapFree=0/0 [pid=28591] ppid=28590 vsize=102404 CPUtime=42.23 /proc/28591/stat : 28591 (cupt) R 28590 28591 17872 34816 17872 4202496 23540 7205 0 0 4200 16 4 3 20 0 1 0 28566980 104861696 15181 18446744073709551615 4194304 5184042 140733801379648 140733801373064 139913946123614 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28591/statm: 25601 15181 842 242 0 18163 0 Current children cumulated CPU time (s) 42.23 Current children cumulated vsize (KiB) 102404 [startup+42.5002 s] /proc/loadavg: 1.00 0.99 0.91 2/56 28619 /proc/meminfo: memFree=246964/1022884 swapFree=0/0 [pid=28591] ppid=28590 vsize=102404 CPUtime=42.33 /proc/28591/stat : 28591 (cupt) R 28590 28591 17872 34816 17872 4202496 23549 7205 0 0 4210 16 4 3 20 0 1 0 28566980 104861696 15190 18446744073709551615 4194304 5184042 140733801379648 140733801373864 139913954043181 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/28591/statm: 25601 15190 842 242 0 18163 0 Current children cumulated CPU time (s) 42.33 Current children cumulated vsize (KiB) 102404 Child status: 1 Real time (s): 42.5925 CPU time (s): 42.4307 CPU user time (s): 42.2226 CPU system time (s): 0.208013 CPU usage (%): 99.6201 Max. virtual memory (cumulated for all children) (KiB): 102404 getrusage(RUSAGE_CHILDREN,...) data: user time used= 42.2226 system time used= 0.208013 maximum resident set size= 75920 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 30786 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= 666 runsolver used 0 second user time and 0.176011 second system time The end