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/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.01 1.04 0.99 2/55 21757
/proc/meminfo: memFree=907960/1022884 swapFree=0/0
[pid=21757] ppid=21756 vsize=3152 CPUtime=0
/proc/21757/stat : 21757 (runsolver) R 21756 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28559052 3227648 33 18446744073709551615 134512640 134586868 4288140240 4288138288 4151481392 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/21757/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.120039 s]
/proc/loadavg: 1.01 1.04 0.99 2/55 21757
/proc/meminfo: memFree=907960/1022884 swapFree=0/0
[pid=21757] ppid=21756 vsize=89152 CPUtime=0.11
/proc/21757/stat : 21757 (aptitude) R 21756 21757 17863 34816 17863 4202496 7767 1709 0 0 9 2 0 0 20 0 1 0 28559052 91291648 7566 18446744073709551615 139672910192640 139672914499992 140735568556032 140735568547296 139672905035840 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21757/statm: 22288 7566 6656 1052 0 858 0
Current children cumulated CPU time (s) 0.11
Current children cumulated vsize (KiB) 89152

[startup+0.200286 s]
/proc/loadavg: 1.01 1.04 0.99 2/55 21757
/proc/meminfo: memFree=907960/1022884 swapFree=0/0
[pid=21757] ppid=21756 vsize=89152 CPUtime=0.19
/proc/21757/stat : 21757 (aptitude) R 21756 21757 17863 34816 17863 4202496 7870 1709 0 0 17 2 0 0 20 0 1 0 28559052 91291648 7661 18446744073709551615 139672910192640 139672914499992 140735568556032 140735568545808 139672904915517 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21757/statm: 22288 7661 6726 1052 0 858 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 89152

[startup+0.30027 s]
/proc/loadavg: 1.01 1.04 0.99 2/55 21757
/proc/meminfo: memFree=907960/1022884 swapFree=0/0
[pid=21757] ppid=21756 vsize=101864 CPUtime=0.28
/proc/21757/stat : 21757 (aptitude) R 21756 21757 17863 34816 17863 4202496 11709 1709 0 0 26 2 0 0 20 0 1 0 28559052 104308736 10755 18446744073709551615 139672910192640 139672914499992 140735568556032 140735568545464 139672867379408 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21757/statm: 25466 10755 6746 1052 0 4036 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 101864

[startup+0.700204 s]
/proc/loadavg: 1.01 1.04 0.99 2/55 21757
/proc/meminfo: memFree=907960/1022884 swapFree=0/0
[pid=21757] ppid=21756 vsize=114148 CPUtime=0.68
/proc/21757/stat : 21757 (aptitude) R 21756 21757 17863 34816 17863 4202496 13715 1709 0 0 65 3 0 0 20 0 2 0 28559052 116887552 12086 18446744073709551615 139672910192640 139672914499992 140735568556032 140735568547304 139672912394011 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21757/statm: 28537 12086 6977 1052 0 7107 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 114148

[startup+1.50024 s]
/proc/loadavg: 1.01 1.04 0.99 2/57 21762
/proc/meminfo: memFree=887244/1022884 swapFree=0/0
[pid=21757] ppid=21756 vsize=115568 CPUtime=1.48
/proc/21757/stat : 21757 (aptitude) R 21756 21757 17863 34816 17863 4202496 14597 2206 0 0 143 5 0 0 20 0 2 0 28559052 118341632 12329 18446744073709551615 139672910192640 139672914499992 140735568556032 140735568548056 139672912444121 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21757/statm: 28892 12329 7073 1052 0 7462 0
[pid=21757/tid=21762] ppid=21756 vsize=115568 CPUtime=0
/proc/21757/task/21762/stat : 21762 (aptitude) S 21756 21757 17863 34816 17863 4202560 6 2206 0 0 0 0 0 0 20 0 2 0 28559097 118341632 12329 18446744073709551615 139672910192640 139672914499992 140735568556032 139672813598720 139672878936788 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) 115568

[startup+3.10024 s]
/proc/loadavg: 1.01 1.04 0.99 2/57 21763
/proc/meminfo: memFree=872240/1022884 swapFree=0/0
[pid=21757] ppid=21756 vsize=213464 CPUtime=3.07
/proc/21757/stat : 21757 (aptitude) S 21756 21757 17863 34816 17863 4202496 23686 2206 0 0 299 8 0 0 20 0 2 0 28559052 218587136 20691 18446744073709551615 139672910192640 139672914499992 140735568556032 140735568547792 139672878937675 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21757/statm: 53366 20691 7129 1052 0 31936 0
[pid=21757/tid=21762] ppid=21756 vsize=213464 CPUtime=1.16
/proc/21757/task/21762/stat : 21762 (aptitude) R 21756 21757 17863 34816 17863 4202560 9068 2206 0 0 114 2 0 0 20 0 2 0 28559097 218587136 20691 18446744073709551615 139672910192640 139672914499992 140735568556032 139672813592376 139672867702920 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) 213464

[startup+6.30024 s]
/proc/loadavg: 1.01 1.03 0.99 2/57 21763
/proc/meminfo: memFree=834048/1022884 swapFree=0/0
[pid=21757] ppid=21756 vsize=239272 CPUtime=6.25
/proc/21757/stat : 21757 (aptitude) S 21756 21757 17863 34816 17863 4202496 30150 2206 0 0 615 10 0 0 20 0 2 0 28559052 245014528 27136 18446744073709551615 139672910192640 139672914499992 140735568556032 140735568547792 139672878937675 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21757/statm: 59818 27136 7129 1052 0 38388 0
[pid=21757/tid=21762] ppid=21756 vsize=239272 CPUtime=4.35
/proc/21757/task/21762/stat : 21762 (aptitude) R 21756 21757 17863 34816 17863 4202560 15532 2206 0 0 430 5 0 0 20 0 2 0 28559097 245014528 27136 18446744073709551615 139672910192640 139672914499992 140735568556032 139672813592200 139672867702920 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.25
Current children cumulated vsize (KiB) 239272

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

[startup+6.40031 s]
/proc/loadavg: 1.01 1.03 0.99 2/57 21763
/proc/meminfo: memFree=834048/1022884 swapFree=0/0
[pid=21757] ppid=21756 vsize=239932 CPUtime=6.35
/proc/21757/stat : 21757 (aptitude) S 21756 21757 17863 34816 17863 4202496 30328 2206 0 0 625 10 0 0 20 0 2 0 28559052 245690368 27314 18446744073709551615 139672910192640 139672914499992 140735568556032 140735568547792 139672878937675 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21757/statm: 59983 27314 7129 1052 0 38553 0
[pid=21757/tid=21762] ppid=21756 vsize=239932 CPUtime=4.45
/proc/21757/task/21762/stat : 21762 (aptitude) R 21756 21757 17863 34816 17863 4202560 15710 2206 0 0 440 5 0 0 20 0 2 0 28559097 245690368 27314 18446744073709551615 139672910192640 139672914499992 140735568556032 139672813592296 139672867702837 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.35
Current children cumulated vsize (KiB) 239932

[startup+9.60024 s]
/proc/loadavg: 1.01 1.03 0.99 2/57 21763
/proc/meminfo: memFree=805900/1022884 swapFree=0/0
[pid=21757] ppid=21756 vsize=265108 CPUtime=9.54
/proc/21757/stat : 21757 (aptitude) S 21756 21757 17863 34816 17863 4202496 36885 2206 0 0 941 13 0 0 20 0 2 0 28559052 271470592 33610 18446744073709551615 139672910192640 139672914499992 140735568556032 140735568547792 139672878937675 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21757/statm: 66277 33610 7129 1052 0 44847 0
[pid=21757/tid=21762] ppid=21756 vsize=265108 CPUtime=7.64
/proc/21757/task/21762/stat : 21762 (aptitude) R 21756 21757 17863 34816 17863 4202560 22267 2206 0 0 756 8 0 0 20 0 2 0 28559097 271470592 33610 18446744073709551615 139672910192640 139672914499992 140735568556032 139672813590040 139672912985569 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 9.54
Current children cumulated vsize (KiB) 265108

[startup+11.2002 s]
/proc/loadavg: 1.01 1.03 0.99 2/57 21763
/proc/meminfo: memFree=794988/1022884 swapFree=0/0
[pid=21757] ppid=21756 vsize=273204 CPUtime=11.13
/proc/21757/stat : 21757 (aptitude) S 21756 21757 17863 34816 17863 4202496 38913 2206 0 0 1099 14 0 0 20 0 2 0 28559052 279760896 35638 18446744073709551615 139672910192640 139672914499992 140735568556032 140735568547792 139672878937675 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21757/statm: 68301 35638 7129 1052 0 46871 0
[pid=21757/tid=21762] ppid=21756 vsize=273204 CPUtime=9.22
/proc/21757/task/21762/stat : 21762 (aptitude) R 21756 21757 17863 34816 17863 4202560 24295 2206 0 0 914 8 0 0 20 0 2 0 28559097 279760896 35638 18446744073709551615 139672910192640 139672914499992 140735568556032 139672813592376 139672912888907 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 11.13
Current children cumulated vsize (KiB) 273204

[startup+12.0003 s]
/proc/loadavg: 1.01 1.03 0.99 2/57 21763
/proc/meminfo: memFree=794988/1022884 swapFree=0/0
[pid=21757] ppid=21756 vsize=278264 CPUtime=11.93
/proc/21757/stat : 21757 (aptitude) R 21756 21757 17863 34816 17863 4202496 40487 2206 0 0 1177 16 0 0 20 0 2 0 28559052 284942336 37084 18446744073709551615 139672910192640 139672914499992 140735568556032 140735568546168 139672867683830 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21757/statm: 69566 37084 7178 1052 0 48129 0
[pid=21757/tid=21762] ppid=21756 vsize=278264 CPUtime=9.8
/proc/21757/task/21762/stat : 21762 (aptitude) S 21756 21757 17863 34816 17863 4202560 25509 2206 0 0 970 10 0 0 20 0 2 0 28559097 284942336 37084 18446744073709551615 139672910192640 139672914499992 140735568556032 139672813598720 139672878936788 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 11.93
Current children cumulated vsize (KiB) 278264

[startup+12.4002 s]
/proc/loadavg: 1.01 1.03 0.99 2/57 21763
/proc/meminfo: memFree=787424/1022884 swapFree=0/0
[pid=21757] ppid=21756 vsize=213020 CPUtime=12.33
/proc/21757/stat : 21757 (aptitude) R 21756 21757 17863 34816 17863 4202496 43117 2705 0 0 1212 20 0 1 20 0 1 0 28559052 218132480 20794 18446744073709551615 139672910192640 139672914499992 140735568556032 140735568553112 139672876502048 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21757/statm: 53255 20794 1503 1052 0 37511 0
Current children cumulated CPU time (s) 12.33
Current children cumulated vsize (KiB) 213020

Child status: 0
Real time (s): 12.4211
CPU time (s): 12.3728
CPU user time (s): 12.1328
CPU system time (s): 0.240015
CPU usage (%): 99.6111
Max. virtual memory (cumulated for all children) (KiB): 278264

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 12.1328
system time used= 0.240015
maximum resident set size= 148676
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 45915
page faults= 0
swaps= 0
block input operations= 0
block output operations= 120
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 82
involuntary context switches= 269

runsolver used 0 second user time and 0.060003 second system time

The end