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/31.runsolver.aptitude aptitude -s -y --without-recommends install libfortune-perl debian-reference-pt-br liferea-mozilla kfloppy ktron 

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.12 1.06 1.01 2/55 23180
/proc/meminfo: memFree=869840/1022884 swapFree=0/0
[pid=23180] ppid=23179 vsize=3152 CPUtime=0
/proc/23180/stat : 23180 (runsolver) R 23179 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28861875 3227648 32 18446744073709551615 134512640 134586868 4290525056 4290523104 4152161328 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/23180/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.172088 s]
/proc/loadavg: 1.12 1.06 1.01 2/55 23180
/proc/meminfo: memFree=869840/1022884 swapFree=0/0
[pid=23180] ppid=23179 vsize=100508 CPUtime=0.15
/proc/23180/stat : 23180 (aptitude) R 23179 23180 17863 34816 17863 4202496 10600 1708 0 0 12 3 0 0 20 0 1 0 28861875 102920192 10400 18446744073709551615 140622628343808 140622632651160 140736200213968 140736200205232 140622623743872 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23180/statm: 25127 10400 9225 1052 0 1122 0
Current children cumulated CPU time (s) 0.15
Current children cumulated vsize (KiB) 100508

[startup+0.200285 s]
/proc/loadavg: 1.12 1.06 1.01 2/55 23180
/proc/meminfo: memFree=869840/1022884 swapFree=0/0
[pid=23180] ppid=23179 vsize=100508 CPUtime=0.18
/proc/23180/stat : 23180 (aptitude) R 23179 23180 17863 34816 17863 4202496 10607 1708 0 0 15 3 0 0 20 0 1 0 28861875 102920192 10407 18446744073709551615 140622628343808 140622632651160 140736200213968 140736200205232 140622623743549 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23180/statm: 25127 10407 9232 1052 0 1122 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 100508

[startup+0.30027 s]
/proc/loadavg: 1.12 1.06 1.01 2/55 23180
/proc/meminfo: memFree=869840/1022884 swapFree=0/0
[pid=23180] ppid=23179 vsize=111108 CPUtime=0.29
/proc/23180/stat : 23180 (aptitude) R 23179 23180 17863 34816 17863 4202496 12212 1708 0 0 25 4 0 0 20 0 1 0 28861875 113774592 12004 18446744073709551615 140622628343808 140622632651160 140736200213968 140736200205560 140622630475355 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23180/statm: 27777 12004 9302 1052 0 3772 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 111108

[startup+0.700202 s]
/proc/loadavg: 1.12 1.06 1.01 2/55 23180
/proc/meminfo: memFree=869840/1022884 swapFree=0/0
[pid=23180] ppid=23179 vsize=123288 CPUtime=0.68
/proc/23180/stat : 23180 (aptitude) R 23179 23180 17863 34816 17863 4202496 17029 1708 0 0 60 8 0 0 20 0 2 0 28861875 126246912 14303 18446744073709551615 140622628343808 140622632651160 140736200213968 140736200209752 140622623186400 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23180/statm: 30822 14303 9482 1052 0 6817 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123288

[startup+1.50023 s]
/proc/loadavg: 1.12 1.06 1.01 2/57 23185
/proc/meminfo: memFree=841560/1022884 swapFree=0/0
[pid=23180] ppid=23179 vsize=132416 CPUtime=1.48
/proc/23180/stat : 23180 (aptitude) R 23179 23180 17863 34816 17863 4202496 19432 1708 0 0 138 10 0 0 20 0 2 0 28861875 135593984 16702 18446744073709551615 140622628343808 140622632651160 140736200213968 140736200204320 140622585854048 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23180/statm: 33104 16702 9585 1052 0 9099 0
[pid=23180/tid=23185] ppid=23179 vsize=132416 CPUtime=0
/proc/23180/task/23185/stat : 23185 (aptitude) S 23179 23180 17863 34816 17863 4202560 4 1708 0 0 0 0 0 0 20 0 2 0 28861941 135593984 16702 18446744073709551615 140622628343808 140622632651160 140736200213968 140622519171072 140622597087956 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) 132416

[startup+3.10025 s]
/proc/loadavg: 1.11 1.06 1.01 2/57 23186
/proc/meminfo: memFree=840436/1022884 swapFree=0/0
[pid=23180] ppid=23179 vsize=133792 CPUtime=3.06
/proc/23180/stat : 23180 (aptitude) R 23179 23180 17863 34816 17863 4202496 20573 2207 0 0 294 12 0 0 20 0 2 0 28861875 137003008 16936 18446744073709551615 140622628343808 140622632651160 140736200213968 140736200200784 140622586564943 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23180/statm: 33448 16936 9644 1052 0 9443 0
[pid=23180/tid=23185] ppid=23179 vsize=133792 CPUtime=0
/proc/23180/task/23185/stat : 23185 (aptitude) S 23179 23180 17863 34816 17863 4202560 6 2207 0 0 0 0 0 0 20 0 2 0 28861941 137003008 16936 18446744073709551615 140622628343808 140622632651160 140736200213968 140622519171072 140622597087956 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) 133792

[startup+6.30031 s]
/proc/loadavg: 1.11 1.06 1.01 2/57 23186
/proc/meminfo: memFree=797416/1022884 swapFree=0/0
[pid=23180] ppid=23179 vsize=244504 CPUtime=6.25
/proc/23180/stat : 23180 (aptitude) S 23179 23180 17863 34816 17863 4202496 32856 2207 0 0 606 19 0 0 20 0 2 0 28861875 250372096 28460 18446744073709551615 140622628343808 140622632651160 140736200213968 140736200205728 140622597088843 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23180/statm: 61126 28460 9700 1052 0 37121 0
[pid=23180/tid=23185] ppid=23179 vsize=244504 CPUtime=3.16
/proc/23180/task/23185/stat : 23185 (aptitude) R 23179 23180 17863 34816 17863 4202560 12282 2207 0 0 310 6 0 0 20 0 2 0 28861941 250372096 28460 18446744073709551615 140622628343808 140622632651160 140736200213968 140622519162440 140622585854088 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) 244504

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

[startup+6.40032 s]
/proc/loadavg: 1.11 1.06 1.01 2/57 23186
/proc/meminfo: memFree=797416/1022884 swapFree=0/0
[pid=23180] ppid=23179 vsize=245032 CPUtime=6.35
/proc/23180/stat : 23180 (aptitude) S 23179 23180 17863 34816 17863 4202496 33055 2207 0 0 616 19 0 0 20 0 2 0 28861875 250912768 28584 18446744073709551615 140622628343808 140622632651160 140736200213968 140736200205728 140622597088843 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23180/statm: 61258 28584 9700 1052 0 37253 0
[pid=23180/tid=23185] ppid=23179 vsize=245032 CPUtime=3.26
/proc/23180/task/23185/stat : 23185 (aptitude) R 23179 23180 17863 34816 17863 4202560 12481 2207 0 0 320 6 0 0 20 0 2 0 28861941 250912768 28584 18446744073709551615 140622628343808 140622632651160 140736200213968 140622519162440 140622631136737 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) 245032

[startup+8.00025 s]
/proc/loadavg: 1.10 1.06 1.01 2/57 23186
/proc/meminfo: memFree=780304/1022884 swapFree=0/0
[pid=23180] ppid=23179 vsize=261148 CPUtime=7.94
/proc/23180/stat : 23180 (aptitude) S 23179 23180 17863 34816 17863 4202496 37152 2207 0 0 774 20 0 0 20 0 2 0 28861875 267415552 32607 18446744073709551615 140622628343808 140622632651160 140736200213968 140736200205728 140622597088843 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23180/statm: 65287 32607 9700 1052 0 41282 0
[pid=23180/tid=23185] ppid=23179 vsize=261148 CPUtime=4.86
/proc/23180/task/23185/stat : 23185 (aptitude) R 23179 23180 17863 34816 17863 4202560 16578 2207 0 0 478 8 0 0 20 0 2 0 28861941 267415552 32607 18446744073709551615 140622628343808 140622632651160 140736200213968 140622519162392 140622630976987 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 7.94
Current children cumulated vsize (KiB) 261148

[startup+8.80025 s]
/proc/loadavg: 1.10 1.06 1.01 2/57 23186
/proc/meminfo: memFree=773360/1022884 swapFree=0/0
[pid=23180] ppid=23179 vsize=264768 CPUtime=8.74
/proc/23180/stat : 23180 (aptitude) R 23179 23180 17863 34816 17863 4202496 40715 2207 0 0 851 23 0 0 20 0 2 0 28861875 271122432 33613 18446744073709551615 140622628343808 140622632651160 140736200213968 140736200206168 140622630545179 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23180/statm: 66192 33613 9750 1052 0 42180 0
[pid=23180/tid=23185] ppid=23179 vsize=264768 CPUtime=5.3
/proc/23180/task/23185/stat : 23185 (aptitude) S 23179 23180 17863 34816 17863 4202560 17466 2207 0 0 522 8 0 0 20 0 2 0 28861941 271122432 33613 18446744073709551615 140622628343808 140622632651160 140736200213968 140622519171072 140622597087956 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 8.74
Current children cumulated vsize (KiB) 264768

[startup+9.00024 s]
/proc/loadavg: 1.10 1.06 1.01 2/57 23186
/proc/meminfo: memFree=773360/1022884 swapFree=0/0
[pid=23180] ppid=23179 vsize=264768 CPUtime=8.95
/proc/23180/stat : 23180 (aptitude) R 23179 23180 17863 34816 17863 4202496 40981 2707 0 0 866 27 1 1 20 0 2 0 28861875 271122432 33770 18446744073709551615 140622628343808 140622632651160 140736200213968 140736200204216 140622623042148 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23180/statm: 66192 33770 9750 1052 0 42180 0
[pid=23180/tid=23185] ppid=23179 vsize=264768 CPUtime=5.32
/proc/23180/task/23185/stat : 23185 (aptitude) S 23179 23180 17863 34816 17863 4202560 17466 2707 0 0 522 8 1 1 20 0 2 0 28861941 271122432 33770 18446744073709551615 140622628343808 140622632651160 140736200213968 140622519171072 140622597087956 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 8.95
Current children cumulated vsize (KiB) 264768

[startup+9.10023 s]
/proc/loadavg: 1.10 1.06 1.01 2/57 23186
/proc/meminfo: memFree=773360/1022884 swapFree=0/0
[pid=23180] ppid=23179 vsize=264768 CPUtime=9.05
/proc/23180/stat : 23180 (aptitude) R 23179 23180 17863 34816 17863 4202496 41099 2707 0 0 872 31 1 1 20 0 2 0 28861875 271122432 33593 18446744073709551615 140622628343808 140622632651160 140736200213968 140736200205784 140622586187845 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23180/statm: 66192 33593 9750 1052 0 42180 0
[pid=23180/tid=23185] ppid=23179 vsize=264768 CPUtime=5.32
/proc/23180/task/23185/stat : 23185 (aptitude) S 23179 23180 17863 34816 17863 4202560 17466 2707 0 0 522 8 1 1 20 0 2 0 28861941 271122432 33593 18446744073709551615 140622628343808 140622632651160 140736200213968 140622519171072 140622597087956 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 9.05
Current children cumulated vsize (KiB) 264768

Child status: 0
Real time (s): 9.13764
CPU time (s): 9.10057
CPU user time (s): 8.74855
CPU system time (s): 0.352022
CPU usage (%): 99.5943
Max. virtual memory (cumulated for all children) (KiB): 264768

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 8.74855
system time used= 0.352022
maximum resident set size= 135428
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 44321
page faults= 0
swaps= 0
block input operations= 0
block output operations= 136
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 73
involuntary context switches= 206

runsolver used 0.012 second user time and 0.036002 second system time

The end