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-sid/logs/9.runsolver.aptitude aptitude -s -y --without-recommends install nrg2iso ipopd ttf-junicode python2.4-svn yacas-proteus 

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.22 1.12 1.03 2/55 25050
/proc/meminfo: memFree=773024/1022884 swapFree=0/0
[pid=25050] ppid=25049 vsize=3152 CPUtime=0
/proc/25050/stat : 25050 (runsolver) R 25049 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29315683 3227648 32 18446744073709551615 134512640 134586868 4293140544 4293138592 4152120368 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/25050/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.185064 s]
/proc/loadavg: 1.22 1.12 1.03 2/55 25050
/proc/meminfo: memFree=773024/1022884 swapFree=0/0
[pid=25050] ppid=25049 vsize=103288 CPUtime=0.17
/proc/25050/stat : 25050 (aptitude) R 25049 25050 17863 34816 17863 4202496 11295 1710 0 0 15 2 0 0 20 0 1 0 29315683 105766912 11096 18446744073709551615 139645518536704 139645522844056 140737429713696 140737429704960 139645476118448 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25050/statm: 25822 11096 9885 1052 0 1159 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 103288

[startup+0.200342 s]
/proc/loadavg: 1.22 1.12 1.03 2/55 25050
/proc/meminfo: memFree=773024/1022884 swapFree=0/0
[pid=25050] ppid=25049 vsize=103288 CPUtime=0.19
/proc/25050/stat : 25050 (aptitude) R 25049 25050 17863 34816 17863 4202496 11300 1710 0 0 17 2 0 0 20 0 1 0 29315683 105766912 11101 18446744073709551615 139645518536704 139645522844056 140737429713696 140737429704960 139645513378115 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25050/statm: 25822 11101 9890 1052 0 1159 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 103288

[startup+0.300271 s]
/proc/loadavg: 1.22 1.12 1.03 2/55 25050
/proc/meminfo: memFree=773024/1022884 swapFree=0/0
[pid=25050] ppid=25049 vsize=103432 CPUtime=0.29
/proc/25050/stat : 25050 (aptitude) R 25049 25050 17863 34816 17863 4202496 11426 1710 0 0 27 2 0 0 20 0 1 0 29315683 105914368 11219 18446744073709551615 139645518536704 139645522844056 140737429713696 140737429703472 139645513390050 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25050/statm: 25858 11219 9956 1052 0 1195 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 103432

[startup+0.700195 s]
/proc/loadavg: 1.22 1.12 1.03 2/55 25050
/proc/meminfo: memFree=773024/1022884 swapFree=0/0
[pid=25050] ppid=25049 vsize=123068 CPUtime=0.68
/proc/25050/stat : 25050 (aptitude) R 25049 25050 17863 34816 17863 4202496 17688 1710 0 0 62 6 0 0 20 0 1 0 29315683 126021632 15964 18446744073709551615 139645518536704 139645522844056 140737429713696 140737429703128 139645476077075 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25050/statm: 30767 15964 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123068

[startup+1.50024 s]
/proc/loadavg: 1.22 1.12 1.03 2/57 25055
/proc/meminfo: memFree=753052/1022884 swapFree=0/0
[pid=25050] ppid=25049 vsize=136052 CPUtime=1.47
/proc/25050/stat : 25050 (aptitude) R 25049 25050 17863 34816 17863 4202496 20640 1710 0 0 140 7 0 0 20 0 2 0 29315683 139317248 17559 18446744073709551615 139645518536704 139645522844056 140737429713696 140737429704968 139645513364524 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25050/statm: 34013 17559 10207 1052 0 9350 0
[pid=25050/tid=25055] ppid=25049 vsize=136052 CPUtime=0
/proc/25050/task/25055/stat : 25055 (aptitude) S 25049 25050 17863 34816 17863 4202560 4 1710 0 0 0 0 0 0 20 0 2 0 29315760 139317248 17559 18446744073709551615 139645518536704 139645522844056 140737429713696 139645406214144 139645487280852 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 136052

[startup+3.10024 s]
/proc/loadavg: 1.22 1.12 1.03 2/57 25055
/proc/meminfo: memFree=742884/1022884 swapFree=0/0
[pid=25050] ppid=25049 vsize=137812 CPUtime=3.06
/proc/25050/stat : 25050 (aptitude) R 25049 25050 17863 34816 17863 4202496 21990 2208 0 0 294 12 0 0 20 0 2 0 29315683 141119488 17934 18446744073709551615 139645518536704 139645522844056 140737429713696 140737429700400 139645476689107 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25050/statm: 34453 17934 10303 1052 0 9790 0
[pid=25050/tid=25055] ppid=25049 vsize=137812 CPUtime=0
/proc/25050/task/25055/stat : 25055 (aptitude) S 25049 25050 17863 34816 17863 4202560 6 2208 0 0 0 0 0 0 20 0 2 0 29315760 141119488 17934 18446744073709551615 139645518536704 139645522844056 140737429713696 139645406214144 139645487280852 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.06
Current children cumulated vsize (KiB) 137812

[startup+6.30025 s]
/proc/loadavg: 1.20 1.12 1.03 2/57 25056
/proc/meminfo: memFree=700724/1022884 swapFree=0/0
[pid=25050] ppid=25049 vsize=186040 CPUtime=6.25
/proc/25050/stat : 25050 (aptitude) S 25049 25050 17863 34816 17863 4202496 34830 2208 0 0 608 17 0 0 20 0 2 0 29315683 190504960 30230 18446744073709551615 139645518536704 139645522844056 140737429713696 140737429705456 139645487281739 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25050/statm: 46510 30230 10359 1052 0 21847 0
[pid=25050/tid=25055] ppid=25049 vsize=186040 CPUtime=2.86
/proc/25050/task/25055/stat : 25055 (aptitude) R 25049 25050 17863 34816 17863 4202560 12840 2208 0 0 282 4 0 0 20 0 2 0 29315760 190504960 30230 18446744073709551615 139645518536704 139645522844056 140737429713696 139645406207720 139645521244608 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) 186040

[startup+12.7002 s]
/proc/loadavg: 1.18 1.12 1.03 2/57 25056
/proc/meminfo: memFree=652488/1022884 swapFree=0/0
[pid=25050] ppid=25049 vsize=295968 CPUtime=12.62
/proc/25050/stat : 25050 (aptitude) S 25049 25050 17863 34816 17863 4202496 46157 2208 0 0 1240 22 0 0 20 0 2 0 29315683 303071232 41295 18446744073709551615 139645518536704 139645522844056 140737429713696 140737429705456 139645487281739 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25050/statm: 73992 41295 10360 1052 0 49329 0
[pid=25050/tid=25055] ppid=25049 vsize=295968 CPUtime=9.23
/proc/25050/task/25055/stat : 25055 (aptitude) R 25049 25050 17863 34816 17863 4202560 24166 2208 0 0 914 9 0 0 20 0 2 0 29315760 303071232 41295 18446744073709551615 139645518536704 139645522844056 140737429713696 139645406207072 139645521363470 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.62
Current children cumulated vsize (KiB) 295968

[startup+25.5003 s]
/proc/loadavg: 1.14 1.11 1.03 2/57 25056
/proc/meminfo: memFree=577716/1022884 swapFree=0/0
[pid=25050] ppid=25049 vsize=367456 CPUtime=25.35
/proc/25050/stat : 25050 (aptitude) S 25049 25050 17863 34816 17863 4202496 64253 2208 0 0 2502 33 0 0 20 0 2 0 29315683 376274944 59186 18446744073709551615 139645518536704 139645522844056 140737429713696 140737429705456 139645487281739 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25050/statm: 91864 59186 10360 1052 0 67201 0
[pid=25050/tid=25055] ppid=25049 vsize=367456 CPUtime=21.96
/proc/25050/task/25055/stat : 25055 (aptitude) R 25049 25050 17863 34816 17863 4202560 42262 2208 0 0 2176 20 0 0 20 0 2 0 29315760 376274944 59186 18446744073709551615 139645518536704 139645522844056 140737429713696 139645406205512 139645521238101 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.35
Current children cumulated vsize (KiB) 367456

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

[startup+25.6003 s]
/proc/loadavg: 1.14 1.11 1.03 2/57 25056
/proc/meminfo: memFree=577716/1022884 swapFree=0/0
[pid=25050] ppid=25049 vsize=367720 CPUtime=25.45
/proc/25050/stat : 25050 (aptitude) S 25049 25050 17863 34816 17863 4202496 64308 2208 0 0 2512 33 0 0 20 0 2 0 29315683 376545280 59241 18446744073709551615 139645518536704 139645522844056 140737429713696 140737429705456 139645487281739 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25050/statm: 91930 59241 10360 1052 0 67267 0
[pid=25050/tid=25055] ppid=25049 vsize=367720 CPUtime=22.06
/proc/25050/task/25055/stat : 25055 (aptitude) R 25049 25050 17863 34816 17863 4202560 42317 2208 0 0 2186 20 0 0 20 0 2 0 29315760 376545280 59241 18446744073709551615 139645518536704 139645522844056 140737429713696 139645406205464 139645521363557 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.45
Current children cumulated vsize (KiB) 367720

[startup+28.8002 s]
/proc/loadavg: 1.13 1.11 1.03 2/57 25056
/proc/meminfo: memFree=561348/1022884 swapFree=0/0
[pid=25050] ppid=25049 vsize=383472 CPUtime=28.57
/proc/25050/stat : 25050 (aptitude) S 25049 25050 17863 34816 17863 4202496 68266 2208 0 0 2822 35 0 0 20 0 2 0 29315683 392675328 63180 18446744073709551615 139645518536704 139645522844056 140737429713696 140737429705456 139645487281739 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25050/statm: 95868 63180 10360 1052 0 71205 0
[pid=25050/tid=25055] ppid=25049 vsize=383472 CPUtime=25.17
/proc/25050/task/25055/stat : 25055 (aptitude) R 25049 25050 17863 34816 17863 4202560 46275 2208 0 0 2495 22 0 0 20 0 2 0 29315760 392675328 63180 18446744073709551615 139645518536704 139645522844056 140737429713696 139645406205464 139645484841964 0 134217728 4096 0 0 0 0 -1 0 0 0 7 0 0
Current children cumulated CPU time (s) 28.57
Current children cumulated vsize (KiB) 383472

[startup+32.0032 s]
/proc/loadavg: 1.13 1.11 1.03 2/57 25056
/proc/meminfo: memFree=545352/1022884 swapFree=0/0
[pid=25050] ppid=25049 vsize=399656 CPUtime=31.75
/proc/25050/stat : 25050 (aptitude) S 25049 25050 17863 34816 17863 4202496 72299 2208 0 0 3138 37 0 0 20 0 2 0 29315683 409247744 67213 18446744073709551615 139645518536704 139645522844056 140737429713696 140737429705456 139645487281739 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25050/statm: 99914 67213 10360 1052 0 75251 0
[pid=25050/tid=25055] ppid=25049 vsize=399656 CPUtime=28.36
/proc/25050/task/25055/stat : 25055 (aptitude) R 25049 25050 17863 34816 17863 4202560 50308 2208 0 0 2812 24 0 0 20 0 2 0 29315760 409247744 67213 18446744073709551615 139645518536704 139645522844056 140737429713696 139645406205464 139645520747613 0 134217728 4096 0 0 0 0 -1 0 0 0 7 0 0
Current children cumulated CPU time (s) 31.75
Current children cumulated vsize (KiB) 399656

[startup+32.8002 s]
/proc/loadavg: 1.13 1.11 1.03 2/57 25056
/proc/meminfo: memFree=545352/1022884 swapFree=0/0
[pid=25050] ppid=25049 vsize=404224 CPUtime=32.56
/proc/25050/stat : 25050 (aptitude) S 25049 25050 17863 34816 17863 4202496 73426 2208 0 0 3218 38 0 0 20 0 2 0 29315683 413925376 68340 18446744073709551615 139645518536704 139645522844056 140737429713696 140737429705456 139645487281739 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25050/statm: 101056 68340 10360 1052 0 76393 0
[pid=25050/tid=25055] ppid=25049 vsize=404224 CPUtime=29.16
/proc/25050/task/25055/stat : 25055 (aptitude) R 25049 25050 17863 34816 17863 4202560 51435 2208 0 0 2891 25 0 0 20 0 2 0 29315760 413925376 68340 18446744073709551615 139645518536704 139645522844056 140737429713696 139645406207672 139645476036888 0 134217728 4096 0 0 0 0 -1 0 0 0 7 0 0
Current children cumulated CPU time (s) 32.56
Current children cumulated vsize (KiB) 404224

[startup+33.6002 s]
/proc/loadavg: 1.12 1.11 1.03 2/57 25056
/proc/meminfo: memFree=539400/1022884 swapFree=0/0
[pid=25050] ppid=25049 vsize=404436 CPUtime=33.34
/proc/25050/stat : 25050 (aptitude) R 25049 25050 17863 34816 17863 4202496 76298 2208 0 0 3296 38 0 0 20 0 2 0 29315683 414142464 68612 18446744073709551615 139645518536704 139645522844056 140737429713696 140737429705464 139645513453680 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25050/statm: 101109 68612 10409 1052 0 76439 0
[pid=25050/tid=25055] ppid=25049 vsize=404436 CPUtime=29.18
/proc/25050/task/25055/stat : 25055 (aptitude) S 25049 25050 17863 34816 17863 4202560 51474 2208 0 0 2893 25 0 0 20 0 2 0 29315760 414142464 68612 18446744073709551615 139645518536704 139645522844056 140737429713696 139645406214144 139645487280852 0 134217728 4096 0 0 0 0 -1 0 0 0 7 0 0
Current children cumulated CPU time (s) 33.34
Current children cumulated vsize (KiB) 404436

[startup+33.8002 s]
/proc/loadavg: 1.12 1.11 1.03 2/57 25056
/proc/meminfo: memFree=539400/1022884 swapFree=0/0
[pid=25050] ppid=25049 vsize=404436 CPUtime=33.55
/proc/25050/stat : 25050 (aptitude) R 25049 25050 17863 34816 17863 4202496 76480 2707 0 0 3309 44 1 1 20 0 2 0 29315683 414142464 68663 18446744073709551615 139645518536704 139645522844056 140737429713696 140737429703784 139645476380741 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25050/statm: 101109 68663 10409 1052 0 76439 0
[pid=25050/tid=25055] ppid=25049 vsize=404436 CPUtime=29.2
/proc/25050/task/25055/stat : 25055 (aptitude) S 25049 25050 17863 34816 17863 4202560 51474 2707 0 0 2893 25 1 1 20 0 2 0 29315760 414142464 68663 18446744073709551615 139645518536704 139645522844056 140737429713696 139645406214144 139645487280852 0 134217728 4096 0 0 0 0 -1 0 0 0 7 0 0
Current children cumulated CPU time (s) 33.55
Current children cumulated vsize (KiB) 404436

[startup+33.9002 s]
/proc/loadavg: 1.12 1.11 1.03 2/57 25056
/proc/meminfo: memFree=539400/1022884 swapFree=0/0
[pid=25050] ppid=25049 vsize=404436 CPUtime=33.65
/proc/25050/stat : 25050 (aptitude) R 25049 25050 17863 34816 17863 4202496 76623 2707 0 0 3313 50 1 1 20 0 2 0 29315683 414142464 68543 18446744073709551615 139645518536704 139645522844056 140737429713696 140737429705512 139645476027998 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25050/statm: 101109 68543 10409 1052 0 76439 0
[pid=25050/tid=25055] ppid=25049 vsize=404436 CPUtime=29.2
/proc/25050/task/25055/stat : 25055 (aptitude) S 25049 25050 17863 34816 17863 4202560 51474 2707 0 0 2893 25 1 1 20 0 2 0 29315760 414142464 68543 18446744073709551615 139645518536704 139645522844056 140737429713696 139645406214144 139645487280852 0 134217728 4096 0 0 0 0 -1 0 0 0 7 0 0
Current children cumulated CPU time (s) 33.65
Current children cumulated vsize (KiB) 404436

Child status: 0
Real time (s): 33.9854
CPU time (s): 33.7461
CPU user time (s): 33.1661
CPU system time (s): 0.580036
CPU usage (%): 99.296
Max. virtual memory (cumulated for all children) (KiB): 404436

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 33.1661
system time used= 0.580036
maximum resident set size= 275040
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 79837
page faults= 0
swaps= 0
block input operations= 0
block output operations= 160
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 128
involuntary context switches= 623

runsolver used 0.056003 second user time and 0.100006 second system time

The end