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/76.runsolver.aptitude aptitude -s -y --without-recommends install python2.4-reportlab quack-el acl2-books-certs steptalk curl 

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.03 1.08 1.02 2/55 23819
/proc/meminfo: memFree=868384/1022884 swapFree=0/0
[pid=23819] ppid=23818 vsize=3152 CPUtime=0
/proc/23819/stat : 23819 (runsolver) R 23818 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29052791 3227648 33 18446744073709551615 134512640 134586868 4289848192 4289846240 4151694384 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/23819/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.195045 s]
/proc/loadavg: 1.03 1.08 1.02 2/55 23819
/proc/meminfo: memFree=868384/1022884 swapFree=0/0
[pid=23819] ppid=23818 vsize=100508 CPUtime=0.18
/proc/23819/stat : 23819 (aptitude) R 23818 23819 17863 34816 17863 4202496 10608 1709 0 0 16 1 1 0 20 0 1 0 29052791 102920192 10406 18446744073709551615 139958839853056 139958844160408 140735724094512 140735724085776 139958840583312 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23819/statm: 25127 10406 9231 1052 0 1122 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 100508

[startup+0.200271 s]
/proc/loadavg: 1.03 1.08 1.02 2/55 23819
/proc/meminfo: memFree=868384/1022884 swapFree=0/0
[pid=23819] ppid=23818 vsize=100508 CPUtime=0.2
/proc/23819/stat : 23819 (aptitude) R 23818 23819 17863 34816 17863 4202496 10609 1709 0 0 17 2 1 0 20 0 1 0 29052791 102920192 10407 18446744073709551615 139958839853056 139958844160408 140735724094512 140735724085776 139958834693974 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23819/statm: 25127 10407 9232 1052 0 1122 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 100508

[startup+0.300264 s]
/proc/loadavg: 1.03 1.08 1.02 2/55 23819
/proc/meminfo: memFree=868384/1022884 swapFree=0/0
[pid=23819] ppid=23818 vsize=111108 CPUtime=0.29
/proc/23819/stat : 23819 (aptitude) R 23818 23819 17863 34816 17863 4202496 12498 1709 0 0 26 2 1 0 20 0 1 0 29052791 113774592 12288 18446744073709551615 139958839853056 139958844160408 140735724094512 140735724086104 139958841984595 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23819/statm: 27777 12288 9302 1052 0 3772 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 111108

[startup+0.700199 s]
/proc/loadavg: 1.03 1.08 1.02 2/55 23819
/proc/meminfo: memFree=868384/1022884 swapFree=0/0
[pid=23819] ppid=23818 vsize=123288 CPUtime=0.69
/proc/23819/stat : 23819 (aptitude) R 23818 23819 17863 34816 17863 4202496 17031 1709 0 0 64 4 1 0 20 0 2 0 29052791 126246912 14303 18446744073709551615 139958839853056 139958844160408 140735724094512 140735724090296 139958834696475 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23819/statm: 30822 14303 9482 1052 0 6817 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 123288

[startup+1.50024 s]
/proc/loadavg: 1.03 1.08 1.02 2/57 23824
/proc/meminfo: memFree=840244/1022884 swapFree=0/0
[pid=23819] ppid=23818 vsize=132404 CPUtime=1.48
/proc/23819/stat : 23819 (aptitude) R 23818 23819 17863 34816 17863 4202496 19441 1709 0 0 143 4 1 0 20 0 2 0 29052791 135581696 16709 18446744073709551615 139958839853056 139958844160408 140735724094512 140735724084864 139958797363527 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23819/statm: 33101 16709 9585 1052 0 9096 0
[pid=23819/tid=23824] ppid=23818 vsize=132404 CPUtime=0.01
/proc/23819/task/23824/stat : 23824 (aptitude) S 23818 23819 17863 34816 17863 4202560 4 1709 0 0 0 0 1 0 20 0 2 0 29052857 135581696 16709 18446744073709551615 139958839853056 139958844160408 140735724094512 139958730680320 139958808597204 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 132404

[startup+3.10024 s]
/proc/loadavg: 1.03 1.08 1.02 2/57 23825
/proc/meminfo: memFree=838996/1022884 swapFree=0/0
[pid=23819] ppid=23818 vsize=133816 CPUtime=3.07
/proc/23819/stat : 23819 (aptitude) R 23818 23819 17863 34816 17863 4202496 20609 2206 0 0 298 8 1 0 20 0 2 0 29052791 137027584 16953 18446744073709551615 139958839853056 139958844160408 140735724094512 140735724081328 139958806158316 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23819/statm: 33454 16953 9644 1052 0 9449 0
[pid=23819/tid=23824] ppid=23818 vsize=133816 CPUtime=0.01
/proc/23819/task/23824/stat : 23824 (aptitude) S 23818 23819 17863 34816 17863 4202560 6 2206 0 0 0 0 1 0 20 0 2 0 29052857 137027584 16953 18446744073709551615 139958839853056 139958844160408 140735724094512 139958730680320 139958808597204 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 133816

[startup+6.30024 s]
/proc/loadavg: 1.03 1.08 1.02 2/57 23825
/proc/meminfo: memFree=795232/1022884 swapFree=0/0
[pid=23819] ppid=23818 vsize=180412 CPUtime=6.26
/proc/23819/stat : 23819 (aptitude) S 23818 23819 17863 34816 17863 4202496 33247 2206 0 0 613 12 1 0 20 0 2 0 29052791 184741888 28824 18446744073709551615 139958839853056 139958844160408 140735724094512 140735724086272 139958808598091 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23819/statm: 45103 28824 9700 1052 0 21098 0
[pid=23819/tid=23824] ppid=23818 vsize=180412 CPUtime=3.17
/proc/23819/task/23824/stat : 23824 (aptitude) R 23818 23819 17863 34816 17863 4202560 12638 2206 0 0 312 4 1 0 20 0 2 0 29052857 184741888 28824 18446744073709551615 139958839853056 139958844160408 140735724094512 139958730671688 139958797363577 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.26
Current children cumulated vsize (KiB) 180412

[startup+12.7002 s]
/proc/loadavg: 1.03 1.08 1.02 2/57 23825
/proc/meminfo: memFree=750840/1022884 swapFree=0/0
[pid=23819] ppid=23818 vsize=290852 CPUtime=12.63
/proc/23819/stat : 23819 (aptitude) S 23818 23819 17863 34816 17863 4202496 44761 2206 0 0 1245 17 1 0 20 0 2 0 29052791 297832448 40041 18446744073709551615 139958839853056 139958844160408 140735724094512 140735724086272 139958808598091 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23819/statm: 72713 40041 9701 1052 0 48708 0
[pid=23819/tid=23824] ppid=23818 vsize=290852 CPUtime=9.53
/proc/23819/task/23824/stat : 23824 (aptitude) R 23818 23819 17863 34816 17863 4202560 24151 2206 0 0 944 8 1 0 20 0 2 0 29052857 297832448 40041 18446744073709551615 139958839853056 139958844160408 140735724094512 139958730673928 139958842500677 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.63
Current children cumulated vsize (KiB) 290852

Solver just ended. Dumping a history of the last processes samples

[startup+12.8003 s]
/proc/loadavg: 1.03 1.08 1.02 2/57 23825
/proc/meminfo: memFree=750840/1022884 swapFree=0/0
[pid=23819] ppid=23818 vsize=292040 CPUtime=12.73
/proc/23819/stat : 23819 (aptitude) S 23818 23819 17863 34816 17863 4202496 45057 2206 0 0 1254 18 1 0 20 0 2 0 29052791 299048960 40334 18446744073709551615 139958839853056 139958844160408 140735724094512 140735724086272 139958808598091 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23819/statm: 73010 40334 9701 1052 0 49005 0
[pid=23819/tid=23824] ppid=23818 vsize=292040 CPUtime=9.64
/proc/23819/task/23824/stat : 23824 (aptitude) R 23818 23819 17863 34816 17863 4202560 24447 2206 0 0 954 9 1 0 20 0 2 0 29052857 299048960 40334 18446744073709551615 139958839853056 139958844160408 140735724094512 139958730671640 139958842645985 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.73
Current children cumulated vsize (KiB) 292040

[startup+13.6002 s]
/proc/loadavg: 1.03 1.08 1.02 2/57 23825
/proc/meminfo: memFree=741292/1022884 swapFree=0/0
[pid=23819] ppid=23818 vsize=295532 CPUtime=13.53
/proc/23819/stat : 23819 (aptitude) R 23818 23819 17863 34816 17863 4202496 48574 2206 0 0 1332 20 1 0 20 0 2 0 29052791 302624768 41275 18446744073709551615 139958839853056 139958844160408 140735724094512 140735724086712 139958842059431 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23819/statm: 73883 41275 9751 1052 0 49871 0
[pid=23819/tid=23824] ppid=23818 vsize=295532 CPUtime=10
/proc/23819/task/23824/stat : 23824 (aptitude) S 23818 23819 17863 34816 17863 4202560 25285 2206 0 0 989 10 1 0 20 0 2 0 29052857 302624768 41275 18446744073709551615 139958839853056 139958844160408 140735724094512 139958730680320 139958808597204 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 13.53
Current children cumulated vsize (KiB) 295532

[startup+13.8003 s]
/proc/loadavg: 1.03 1.08 1.02 2/57 23825
/proc/meminfo: memFree=741292/1022884 swapFree=0/0
[pid=23819] ppid=23818 vsize=295532 CPUtime=13.73
/proc/23819/stat : 23819 (aptitude) R 23818 23819 17863 34816 17863 4202496 48869 2705 0 0 1346 25 1 1 20 0 2 0 29052791 302624768 41455 18446744073709551615 139958839853056 139958844160408 140735724094512 140735724085672 139958797697093 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23819/statm: 73883 41455 9751 1052 0 49871 0
[pid=23819/tid=23824] ppid=23818 vsize=295532 CPUtime=10.01
/proc/23819/task/23824/stat : 23824 (aptitude) S 23818 23819 17863 34816 17863 4202560 25285 2705 0 0 989 10 1 1 20 0 2 0 29052857 302624768 41455 18446744073709551615 139958839853056 139958844160408 140735724094512 139958730680320 139958808597204 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 13.73
Current children cumulated vsize (KiB) 295532

[startup+13.9002 s]
/proc/loadavg: 1.03 1.08 1.02 2/57 23825
/proc/meminfo: memFree=741292/1022884 swapFree=0/0
[pid=23819] ppid=23818 vsize=295532 CPUtime=13.84
/proc/23819/stat : 23819 (aptitude) R 23818 23819 17863 34816 17863 4202496 49006 2705 0 0 1354 28 1 1 20 0 2 0 29052791 302624768 41272 18446744073709551615 139958839853056 139958844160408 140735724094512 140735724086488 139958797353330 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23819/statm: 73883 41272 9751 1052 0 49871 0
[pid=23819/tid=23824] ppid=23818 vsize=295532 CPUtime=10.01
/proc/23819/task/23824/stat : 23824 (aptitude) S 23818 23819 17863 34816 17863 4202560 25285 2705 0 0 989 10 1 1 20 0 2 0 29052857 302624768 41272 18446744073709551615 139958839853056 139958844160408 140735724094512 139958730680320 139958808597204 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 13.84
Current children cumulated vsize (KiB) 295532

Child status: 0
Real time (s): 13.9503
CPU time (s): 13.8929
CPU user time (s): 13.5688
CPU system time (s): 0.32402
CPU usage (%): 99.5885
Max. virtual memory (cumulated for all children) (KiB): 295532

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 13.5688
system time used= 0.32402
maximum resident set size= 166200
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 52239
page faults= 0
swaps= 0
block input operations= 0
block output operations= 144
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 83
involuntary context switches= 284

runsolver used 0.012 second user time and 0.056003 second system time

The end