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/40.runsolver.aptitude aptitude -s -y --without-recommends install x-window-system-core libsub-uplevel-perl python2.2-docutils python-rpy mendexk 

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.33 1.14 1.05 2/55 25562
/proc/meminfo: memFree=749672/1022884 swapFree=0/0
[pid=25562] ppid=25561 vsize=3152 CPUtime=0
/proc/25562/stat : 25562 (runsolver) R 25561 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29484836 3227648 32 18446744073709551615 134512640 134586868 4287057584 4287055632 4151911472 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/25562/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.129978 s]
/proc/loadavg: 1.33 1.14 1.05 2/55 25562
/proc/meminfo: memFree=749672/1022884 swapFree=0/0
[pid=25562] ppid=25561 vsize=103288 CPUtime=0.11
/proc/25562/stat : 25562 (aptitude) R 25561 25562 17863 34816 17863 4202496 11234 1708 0 0 10 1 0 0 20 0 1 0 29484836 105766912 11036 18446744073709551615 140304383107072 140304387414424 140734379973984 140734379965248 140304377952005 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25562/statm: 25822 11036 9824 1052 0 1159 0
Current children cumulated CPU time (s) 0.11
Current children cumulated vsize (KiB) 103288

[startup+0.20034 s]
/proc/loadavg: 1.33 1.14 1.05 2/55 25562
/proc/meminfo: memFree=749672/1022884 swapFree=0/0
[pid=25562] ppid=25561 vsize=103288 CPUtime=0.18
/proc/25562/stat : 25562 (aptitude) R 25561 25562 17863 34816 17863 4202496 11299 1708 0 0 17 1 0 0 20 0 1 0 29484836 105766912 11101 18446744073709551615 140304383107072 140304387414424 140734379973984 140734379965248 140304377928928 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25562/statm: 25822 11101 9889 1052 0 1159 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 103288

[startup+0.300345 s]
/proc/loadavg: 1.33 1.14 1.05 2/55 25562
/proc/meminfo: memFree=749672/1022884 swapFree=0/0
[pid=25562] ppid=25561 vsize=103432 CPUtime=0.28
/proc/25562/stat : 25562 (aptitude) R 25561 25562 17863 34816 17863 4202496 11426 1708 0 0 26 2 0 0 20 0 1 0 29484836 105914368 11220 18446744073709551615 140304383107072 140304387414424 140734379973984 140734379963760 140304377960394 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25562/statm: 25858 11220 9956 1052 0 1195 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 103432

[startup+0.700216 s]
/proc/loadavg: 1.33 1.14 1.05 2/55 25562
/proc/meminfo: memFree=749672/1022884 swapFree=0/0
[pid=25562] ppid=25561 vsize=123068 CPUtime=0.68
/proc/25562/stat : 25562 (aptitude) R 25561 25562 17863 34816 17863 4202496 17687 1708 0 0 62 6 0 0 20 0 1 0 29484836 126021632 15965 18446744073709551615 140304383107072 140304387414424 140734379973984 140734379963416 140304351863152 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25562/statm: 30767 15965 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123068

[startup+1.50026 s]
/proc/loadavg: 1.33 1.14 1.05 2/57 25567
/proc/meminfo: memFree=729700/1022884 swapFree=0/0
[pid=25562] ppid=25561 vsize=136068 CPUtime=1.47
/proc/25562/stat : 25562 (aptitude) R 25561 25562 17863 34816 17863 4202496 20645 1708 0 0 141 6 0 0 20 0 2 0 29484836 139333632 17564 18446744073709551615 140304383107072 140304387414424 140734379973984 140734379965256 140304377941088 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25562/statm: 34017 17564 10207 1052 0 9354 0
[pid=25562/tid=25567] ppid=25561 vsize=136068 CPUtime=0
/proc/25562/task/25567/stat : 25567 (aptitude) S 25561 25562 17863 34816 17863 4202560 4 1708 0 0 0 0 0 0 20 0 2 0 29484913 139333632 17564 18446744073709551615 140304383107072 140304387414424 140734379973984 140304270784512 140304351851220 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) 136068

[startup+3.10037 s]
/proc/loadavg: 1.33 1.14 1.05 2/57 25567
/proc/meminfo: memFree=719408/1022884 swapFree=0/0
[pid=25562] ppid=25561 vsize=137840 CPUtime=3.07
/proc/25562/stat : 25562 (aptitude) R 25561 25562 17863 34816 17863 4202496 22020 2207 0 0 295 12 0 0 20 0 2 0 29484836 141148160 17956 18446744073709551615 140304383107072 140304387414424 140734379973984 140734379960688 140304385308443 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25562/statm: 34460 17956 10303 1052 0 9797 0
[pid=25562/tid=25567] ppid=25561 vsize=137840 CPUtime=0
/proc/25562/task/25567/stat : 25567 (aptitude) S 25561 25562 17863 34816 17863 4202560 6 2207 0 0 0 0 0 0 20 0 2 0 29484913 141148160 17956 18446744073709551615 140304383107072 140304387414424 140734379973984 140304270784512 140304351851220 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) 137840

[startup+6.30024 s]
/proc/loadavg: 1.31 1.14 1.05 2/57 25568
/proc/meminfo: memFree=675388/1022884 swapFree=0/0
[pid=25562] ppid=25561 vsize=253852 CPUtime=6.25
/proc/25562/stat : 25562 (aptitude) S 25561 25562 17863 34816 17863 4202496 35992 2207 0 0 607 18 0 0 20 0 2 0 29484836 259944448 30806 18446744073709551615 140304383107072 140304387414424 140734379973984 140734379965744 140304351852107 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25562/statm: 63463 30806 10359 1052 0 38800 0
[pid=25562/tid=25567] ppid=25561 vsize=253852 CPUtime=2.85
/proc/25562/task/25567/stat : 25567 (aptitude) R 25561 25562 17863 34816 17863 4202560 13971 2207 0 0 279 6 0 0 20 0 2 0 29484913 259944448 30806 18446744073709551615 140304383107072 140304387414424 140734379973984 140304270775832 140304340617312 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) 253852

[startup+12.7004 s]
/proc/loadavg: 1.28 1.14 1.05 2/57 25568
/proc/meminfo: memFree=626532/1022884 swapFree=0/0
[pid=25562] ppid=25561 vsize=300036 CPUtime=12.61
/proc/25562/stat : 25562 (aptitude) S 25561 25562 17863 34816 17863 4202496 47655 2207 0 0 1238 23 0 0 20 0 2 0 29484836 307236864 42316 18446744073709551615 140304383107072 140304387414424 140734379973984 140734379965744 140304351852107 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25562/statm: 75009 42316 10360 1052 0 50346 0
[pid=25562/tid=25567] ppid=25561 vsize=300036 CPUtime=9.22
/proc/25562/task/25567/stat : 25567 (aptitude) R 25561 25562 17863 34816 17863 4202560 25634 2207 0 0 911 11 0 0 20 0 2 0 29484913 307236864 42316 18446744073709551615 140304383107072 140304387414424 140734379973984 140304270775784 140304384742200 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.61
Current children cumulated vsize (KiB) 300036

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

[startup+12.8004 s]
/proc/loadavg: 1.28 1.14 1.05 2/57 25568
/proc/meminfo: memFree=626532/1022884 swapFree=0/0
[pid=25562] ppid=25561 vsize=300564 CPUtime=12.71
/proc/25562/stat : 25562 (aptitude) S 25561 25562 17863 34816 17863 4202496 47804 2207 0 0 1248 23 0 0 20 0 2 0 29484836 307777536 42465 18446744073709551615 140304383107072 140304387414424 140734379973984 140734379965744 140304351852107 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25562/statm: 75141 42465 10360 1052 0 50478 0
[pid=25562/tid=25567] ppid=25561 vsize=300564 CPUtime=9.32
/proc/25562/task/25567/stat : 25567 (aptitude) R 25561 25562 17863 34816 17863 4202560 25783 2207 0 0 921 11 0 0 20 0 2 0 29484913 307777536 42465 18446744073709551615 140304383107072 140304387414424 140734379973984 140304270777440 140304385308443 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.71
Current children cumulated vsize (KiB) 300564

[startup+19.2003 s]
/proc/loadavg: 1.24 1.13 1.05 2/57 25568
/proc/meminfo: memFree=582636/1022884 swapFree=0/0
[pid=25562] ppid=25561 vsize=340800 CPUtime=19.08
/proc/25562/stat : 25562 (aptitude) S 25561 25562 17863 34816 17863 4202496 57854 2207 0 0 1879 29 0 0 20 0 2 0 29484836 348979200 52507 18446744073709551615 140304383107072 140304387414424 140734379973984 140734379965744 140304351852107 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25562/statm: 85200 52507 10360 1052 0 60537 0
[pid=25562/tid=25567] ppid=25561 vsize=340800 CPUtime=15.68
/proc/25562/task/25567/stat : 25567 (aptitude) R 25561 25562 17863 34816 17863 4202560 35833 2207 0 0 1551 17 0 0 20 0 2 0 29484913 348979200 52507 18446744073709551615 140304383107072 140304387414424 140734379973984 140304270775832 140304340617679 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 19.08
Current children cumulated vsize (KiB) 340800

[startup+22.4003 s]
/proc/loadavg: 1.24 1.13 1.05 2/57 25568
/proc/meminfo: memFree=565524/1022884 swapFree=0/0
[pid=25562] ppid=25561 vsize=356960 CPUtime=22.27
/proc/25562/stat : 25562 (aptitude) S 25561 25562 17863 34816 17863 4202496 61910 2207 0 0 2196 31 0 0 20 0 2 0 29484836 365527040 56550 18446744073709551615 140304383107072 140304387414424 140734379973984 140734379965744 140304351852107 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25562/statm: 89240 56550 10360 1052 0 64577 0
[pid=25562/tid=25567] ppid=25561 vsize=356960 CPUtime=18.87
/proc/25562/task/25567/stat : 25567 (aptitude) R 25561 25562 17863 34816 17863 4202560 39889 2207 0 0 1868 19 0 0 20 0 2 0 29484913 365527040 56550 18446744073709551615 140304383107072 140304387414424 140734379973984 140304270775832 140304385336026 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 22.27
Current children cumulated vsize (KiB) 356960

[startup+24.0003 s]
/proc/loadavg: 1.22 1.13 1.05 2/57 25568
/proc/meminfo: memFree=559820/1022884 swapFree=0/0
[pid=25562] ppid=25561 vsize=365184 CPUtime=23.84
/proc/25562/stat : 25562 (aptitude) S 25561 25562 17863 34816 17863 4202496 64002 2207 0 0 2352 32 0 0 20 0 2 0 29484836 373948416 58637 18446744073709551615 140304383107072 140304387414424 140734379973984 140734379965744 140304351852107 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25562/statm: 91296 58637 10361 1052 0 66633 0
[pid=25562/tid=25567] ppid=25561 vsize=365184 CPUtime=20.43
/proc/25562/task/25567/stat : 25567 (aptitude) R 25561 25562 17863 34816 17863 4202560 41981 2207 0 0 2024 19 0 0 20 0 2 0 29484913 373948416 58637 18446744073709551615 140304383107072 140304387414424 140734379973984 140304270775832 140304349416427 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0
Current children cumulated CPU time (s) 23.84
Current children cumulated vsize (KiB) 365184

[startup+24.8003 s]
/proc/loadavg: 1.22 1.13 1.05 2/57 25568
/proc/meminfo: memFree=554612/1022884 swapFree=0/0
[pid=25562] ppid=25561 vsize=365780 CPUtime=24.62
/proc/25562/stat : 25562 (aptitude) R 25561 25562 17863 34816 17863 4202496 67034 2207 0 0 2430 32 0 0 20 0 2 0 29484836 374558720 59005 18446744073709551615 140304383107072 140304387414424 140734379973984 140734379965688 140304378003525 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25562/statm: 91445 59005 10410 1052 0 66775 0
[pid=25562/tid=25567] ppid=25561 vsize=365780 CPUtime=20.55
/proc/25562/task/25567/stat : 25567 (aptitude) S 25561 25562 17863 34816 17863 4202560 42116 2207 0 0 2036 19 0 0 20 0 2 0 29484913 374558720 59005 18446744073709551615 140304383107072 140304387414424 140734379973984 140304270784512 140304351851220 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0
Current children cumulated CPU time (s) 24.62
Current children cumulated vsize (KiB) 365780

[startup+25.0003 s]
/proc/loadavg: 1.22 1.13 1.05 2/57 25568
/proc/meminfo: memFree=554612/1022884 swapFree=0/0
[pid=25562] ppid=25561 vsize=365780 CPUtime=24.83
/proc/25562/stat : 25562 (aptitude) R 25561 25562 17863 34816 17863 4202496 67282 2706 0 0 2442 40 0 1 20 0 2 0 29484836 374558720 59106 18446744073709551615 140304383107072 140304387414424 140734379973984 140734379965144 140304340617352 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25562/statm: 91445 59106 10410 1052 0 66775 0
[pid=25562/tid=25567] ppid=25561 vsize=365780 CPUtime=20.56
/proc/25562/task/25567/stat : 25567 (aptitude) S 25561 25562 17863 34816 17863 4202560 42116 2706 0 0 2036 19 0 1 20 0 2 0 29484913 374558720 59106 18446744073709551615 140304383107072 140304387414424 140734379973984 140304270784512 140304351851220 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0
Current children cumulated CPU time (s) 24.83
Current children cumulated vsize (KiB) 365780

[startup+25.1006 s]
/proc/loadavg: 1.22 1.13 1.05 2/57 25568
/proc/meminfo: memFree=554612/1022884 swapFree=0/0
[pid=25562] ppid=25561 vsize=365780 CPUtime=24.93
/proc/25562/stat : 25562 (aptitude) R 25561 25562 17863 34816 17863 4202496 67739 2706 0 0 2448 44 0 1 20 0 2 0 29484836 374558720 56826 18446744073709551615 140304383107072 140304387414424 140734379973984 140734379970248 140304340973034 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25562/statm: 91445 56826 10410 1052 0 66775 0
[pid=25562/tid=25567] ppid=25561 vsize=365780 CPUtime=20.56
/proc/25562/task/25567/stat : 25567 (aptitude) S 25561 25562 17863 34816 17863 4202560 42116 2706 0 0 2036 19 0 1 20 0 2 0 29484913 374558720 56826 18446744073709551615 140304383107072 140304387414424 140734379973984 140304270784512 140304351851220 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0
Current children cumulated CPU time (s) 24.93
Current children cumulated vsize (KiB) 365780

Child status: 0
Real time (s): 25.1583
CPU time (s): 25.0136
CPU user time (s): 24.4975
CPU system time (s): 0.516032
CPU usage (%): 99.4246
Max. virtual memory (cumulated for all children) (KiB): 365780

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 24.4975
system time used= 0.516032
maximum resident set size= 236692
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 70604
page faults= 0
swaps= 0
block input operations= 0
block output operations= 152
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 106
involuntary context switches= 472

runsolver used 0.024001 second user time and 0.104006 second system time

The end