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/139.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends remove dia-common ksig kdebase-data ktuberling m4 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] Current StackSize limit: 8192 KiB [startup+0.178748 s] /proc/loadavg: 1.00 1.00 0.96 2/55 1285 /proc/meminfo: memFree=335288/1022884 swapFree=0/0 [pid=1285] ppid=1284 vsize=34964 CPUtime=0.2 /proc/1285/stat : 1285 (cupt) R 1284 1285 17872 34816 17872 4202496 2205 7201 0 0 12 1 5 2 20 0 1 0 29521894 35803136 2023 18446744073709551615 4194304 5184042 140737175465584 140737175462776 140427307515952 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/1285/statm: 8741 2023 729 242 0 1303 0 Current children cumulated CPU time (s) 0.2 Current children cumulated vsize (KiB) 34964 [startup+0.200273 s] /proc/loadavg: 1.00 1.00 0.96 2/55 1285 /proc/meminfo: memFree=335288/1022884 swapFree=0/0 [pid=1285] ppid=1284 vsize=35492 CPUtime=0.22 /proc/1285/stat : 1285 (cupt) R 1284 1285 17872 34816 17872 4202496 2331 7201 0 0 14 1 5 2 20 0 1 0 29521894 36343808 2149 18446744073709551615 4194304 5184042 140737175465584 140737175462776 140427307647054 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/1285/statm: 8873 2149 729 242 0 1435 0 Current children cumulated CPU time (s) 0.22 Current children cumulated vsize (KiB) 35492 [startup+0.300249 s] /proc/loadavg: 1.00 1.00 0.96 2/55 1285 /proc/meminfo: memFree=335288/1022884 swapFree=0/0 [pid=1285] ppid=1284 vsize=37984 CPUtime=0.33 /proc/1285/stat : 1285 (cupt) R 1284 1285 17872 34816 17872 4202496 3037 7201 0 0 22 4 5 2 20 0 1 0 29521894 38895616 2792 18446744073709551615 4194304 5184042 140737175465584 140737175462776 140427307621878 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/1285/statm: 9496 2792 739 242 0 2058 0 Current children cumulated CPU time (s) 0.33 Current children cumulated vsize (KiB) 37984 [startup+0.700193 s] /proc/loadavg: 1.00 1.00 0.96 2/55 1285 /proc/meminfo: memFree=335288/1022884 swapFree=0/0 [pid=1285] ppid=1284 vsize=63136 CPUtime=0.72 /proc/1285/stat : 1285 (cupt) R 1284 1285 17872 34816 17872 4202496 9435 7201 0 0 58 7 5 2 20 0 1 0 29521894 64651264 9182 18446744073709551615 4194304 5184042 140737175465584 140737175462888 140427307583890 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/1285/statm: 15784 9182 851 242 0 8346 0 Current children cumulated CPU time (s) 0.72 Current children cumulated vsize (KiB) 63136 [startup+1.5002 s] /proc/loadavg: 1.00 1.00 0.96 2/56 1305 /proc/meminfo: memFree=301312/1022884 swapFree=0/0 [pid=1285] ppid=1284 vsize=64348 CPUtime=1.52 /proc/1285/stat : 1285 (cupt) R 1284 1285 17872 34816 17872 4202496 9850 7201 0 0 137 8 5 2 20 0 1 0 29521894 65892352 9403 18446744073709551615 4194304 5184042 140737175465584 140737175463016 140427323910917 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/1285/statm: 16087 9403 851 242 0 8649 0 Current children cumulated CPU time (s) 1.52 Current children cumulated vsize (KiB) 64348 [startup+3.1002 s] /proc/loadavg: 1.00 1.00 0.96 2/56 1305 /proc/meminfo: memFree=300444/1022884 swapFree=0/0 [pid=1285] ppid=1284 vsize=65536 CPUtime=3.11 /proc/1285/stat : 1285 (cupt) R 1284 1285 17872 34816 17872 4202496 10326 7201 0 0 296 8 5 2 20 0 1 0 29521894 67108864 9622 18446744073709551615 4194304 5184042 140737175465584 140737175463016 140427323983533 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/1285/statm: 16384 9622 851 242 0 8946 0 Current children cumulated CPU time (s) 3.11 Current children cumulated vsize (KiB) 65536 [startup+6.30021 s] /proc/loadavg: 1.00 1.00 0.96 2/56 1305 /proc/meminfo: memFree=298956/1022884 swapFree=0/0 [pid=1285] ppid=1284 vsize=68024 CPUtime=6.3 /proc/1285/stat : 1285 (cupt) R 1284 1285 17872 34816 17872 4202496 11275 7201 0 0 614 9 5 2 20 0 1 0 29521894 69656576 10058 18446744073709551615 4194304 5184042 140737175465584 140737175462888 140427323926108 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/1285/statm: 17006 10058 851 242 0 9568 0 Current children cumulated CPU time (s) 6.3 Current children cumulated vsize (KiB) 68024 [startup+12.7002 s] /proc/loadavg: 1.00 1.00 0.96 2/56 1305 /proc/meminfo: memFree=295980/1022884 swapFree=0/0 [pid=1285] ppid=1284 vsize=72120 CPUtime=12.67 /proc/1285/stat : 1285 (cupt) R 1284 1285 17872 34816 17872 4202496 12975 7201 0 0 1250 10 5 2 20 0 1 0 29521894 73850880 10733 18446744073709551615 4194304 5184042 140737175465584 140737175463016 140427307582330 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/1285/statm: 18030 10733 851 242 0 10592 0 Current children cumulated CPU time (s) 12.67 Current children cumulated vsize (KiB) 72120 [startup+25.5002 s] /proc/loadavg: 1.00 1.00 0.96 2/56 1305 /proc/meminfo: memFree=289408/1022884 swapFree=0/0 [pid=1285] ppid=1284 vsize=81348 CPUtime=25.42 /proc/1285/stat : 1285 (cupt) R 1284 1285 17872 34816 17872 4202496 16637 7201 0 0 2522 13 5 2 20 0 1 0 29521894 83300352 12346 18446744073709551615 4194304 5184042 140737175465584 140737175463016 140427323926141 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/1285/statm: 20337 12346 851 242 0 12899 0 Current children cumulated CPU time (s) 25.42 Current children cumulated vsize (KiB) 81348 [startup+51.1002 s] /proc/loadavg: 1.00 1.00 0.96 2/56 1305 /proc/meminfo: memFree=271800/1022884 swapFree=0/0 [pid=1285] ppid=1284 vsize=106116 CPUtime=50.91 /proc/1285/stat : 1285 (cupt) R 1284 1285 17872 34816 17872 4202496 25099 7201 0 0 5067 17 5 2 20 0 1 0 29521894 108662784 16711 18446744073709551615 4194304 5184042 140737175465584 140737175459848 140427316389552 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/1285/statm: 26529 16711 851 242 0 19091 0 Current children cumulated CPU time (s) 50.91 Current children cumulated vsize (KiB) 106116 Solver just ended. Dumping a history of the last processes samples [startup+51.2003 s] /proc/loadavg: 1.00 1.00 0.96 2/56 1305 /proc/meminfo: memFree=271800/1022884 swapFree=0/0 [pid=1285] ppid=1284 vsize=106116 CPUtime=51.01 /proc/1285/stat : 1285 (cupt) R 1284 1285 17872 34816 17872 4202496 25107 7201 0 0 5077 17 5 2 20 0 1 0 29521894 108662784 16719 18446744073709551615 4194304 5184042 140737175465584 140737175459848 140427323925491 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/1285/statm: 26529 16719 851 242 0 19091 0 Current children cumulated CPU time (s) 51.01 Current children cumulated vsize (KiB) 106116 [startup+64.0002 s] /proc/loadavg: 1.00 1.00 0.96 2/56 1305 /proc/meminfo: memFree=257292/1022884 swapFree=0/0 [pid=1285] ppid=1284 vsize=116596 CPUtime=63.75 /proc/1285/stat : 1285 (cupt) R 1284 1285 17872 34816 17872 4202496 28715 7201 0 0 6349 19 5 2 20 0 1 0 29521894 119394304 20327 18446744073709551615 4194304 5184042 140737175465584 140737175459880 140427323925504 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/1285/statm: 29149 20327 851 242 0 21711 0 Current children cumulated CPU time (s) 63.75 Current children cumulated vsize (KiB) 116596 [startup+70.4002 s] /proc/loadavg: 1.00 1.00 0.96 2/56 1305 /proc/meminfo: memFree=255060/1022884 swapFree=0/0 [pid=1285] ppid=1284 vsize=116596 CPUtime=70.14 /proc/1285/stat : 1285 (cupt) R 1284 1285 17872 34816 17872 4202496 29248 7201 0 0 6987 20 5 2 20 0 1 0 29521894 119394304 20860 18446744073709551615 4194304 5184042 140737175465584 140737175459880 140427323925504 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/1285/statm: 29149 20860 851 242 0 21711 0 Current children cumulated CPU time (s) 70.14 Current children cumulated vsize (KiB) 116596 [startup+73.6002 s] /proc/loadavg: 1.00 1.00 0.96 2/56 1305 /proc/meminfo: memFree=253944/1022884 swapFree=0/0 [pid=1285] ppid=1284 vsize=116728 CPUtime=73.32 /proc/1285/stat : 1285 (cupt) R 1284 1285 17872 34816 17872 4202496 29571 7201 0 0 7305 20 5 2 20 0 1 0 29521894 119529472 21183 18446744073709551615 4194304 5184042 140737175465584 140737175462456 140427323933074 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/1285/statm: 29182 21183 851 242 0 21744 0 Current children cumulated CPU time (s) 73.32 Current children cumulated vsize (KiB) 116728 [startup+75.2002 s] /proc/loadavg: 1.00 1.00 0.96 2/56 1305 /proc/meminfo: memFree=253200/1022884 swapFree=0/0 [pid=1285] ppid=1284 vsize=116728 CPUtime=74.91 /proc/1285/stat : 1285 (cupt) R 1284 1285 17872 34816 17872 4202496 29703 7201 0 0 7464 20 5 2 20 0 1 0 29521894 119529472 21315 18446744073709551615 4194304 5184042 140737175465584 140737175462456 140427323925864 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/1285/statm: 29182 21315 851 242 0 21744 0 Current children cumulated CPU time (s) 74.91 Current children cumulated vsize (KiB) 116728 [startup+75.6002 s] /proc/loadavg: 1.00 1.00 0.96 2/56 1305 /proc/meminfo: memFree=253200/1022884 swapFree=0/0 [pid=1285] ppid=1284 vsize=116728 CPUtime=75.31 /proc/1285/stat : 1285 (cupt) R 1284 1285 17872 34816 17872 4202496 29736 7201 0 0 7504 20 5 2 20 0 1 0 29521894 119529472 21348 18446744073709551615 4194304 5184042 140737175465584 140737175462456 140427323933074 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/1285/statm: 29182 21348 851 242 0 21744 0 Current children cumulated CPU time (s) 75.31 Current children cumulated vsize (KiB) 116728 [startup+76.0031 s] /proc/loadavg: 1.00 1.00 0.96 2/56 1305 /proc/meminfo: memFree=252828/1022884 swapFree=0/0 [pid=1285] ppid=1284 vsize=116728 CPUtime=75.71 /proc/1285/stat : 1285 (cupt) R 1284 1285 17872 34816 17872 4202496 29769 7201 0 0 7544 20 5 2 20 0 1 0 29521894 119529472 21381 18446744073709551615 4194304 5184042 140737175465584 140737175462456 140427323872273 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/1285/statm: 29182 21381 851 242 0 21744 0 Current children cumulated CPU time (s) 75.71 Current children cumulated vsize (KiB) 116728 [startup+76.1002 s] /proc/loadavg: 1.00 1.00 0.96 2/56 1305 /proc/meminfo: memFree=252828/1022884 swapFree=0/0 [pid=1285] ppid=1284 vsize=83448 CPUtime=75.81 /proc/1285/stat : 1285 (cupt) R 1284 1285 17872 34816 17872 4202496 29784 7201 0 0 7553 21 5 2 20 0 1 0 29521894 85450752 14280 18446744073709551615 4194304 5184042 140737175465584 140737175465032 140427324602714 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/1285/statm: 20862 14280 862 242 0 13424 0 Current children cumulated CPU time (s) 75.81 Current children cumulated vsize (KiB) 83448 Child status: 1 Real time (s): 76.1541 CPU time (s): 75.8727 CPU user time (s): 75.6247 CPU system time (s): 0.248015 CPU usage (%): 99.6305 Max. virtual memory (cumulated for all children) (KiB): 116728 getrusage(RUSAGE_CHILDREN,...) data: user time used= 75.6247 system time used= 0.248015 maximum resident set size= 85584 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 37005 page faults= 0 swaps= 0 block input operations= 0 block output operations= 40 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 53 involuntary context switches= 1150 runsolver used 0.156009 second user time and 0.16001 second system time The end