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/57.runsolver.aptitude aptitude -s -y --without-recommends install gxedit slashem-common openoffice.org-l10n-he libwvstreams4.0-doc libgdal1 

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.02 1.06 1.04 2/55 25725
/proc/meminfo: memFree=830444/1022884 swapFree=0/0
[pid=25725] ppid=25724 vsize=3152 CPUtime=0
/proc/25725/stat : 25725 (runsolver) R 25724 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29601131 3227648 32 18446744073709551615 134512640 134586868 4290329344 4290327392 4151247920 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/25725/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.137518 s]
/proc/loadavg: 1.02 1.06 1.04 2/55 25725
/proc/meminfo: memFree=830444/1022884 swapFree=0/0
[pid=25725] ppid=25724 vsize=103288 CPUtime=0.12
/proc/25725/stat : 25725 (aptitude) R 25724 25725 17863 34816 17863 4202496 11258 1708 0 0 10 2 0 0 20 0 1 0 29601131 105766912 11059 18446744073709551615 140075091308544 140075095615896 140737293168864 140737293160128 140075086149096 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25725/statm: 25822 11059 9847 1052 0 1159 0
Current children cumulated CPU time (s) 0.12
Current children cumulated vsize (KiB) 103288

[startup+0.200278 s]
/proc/loadavg: 1.02 1.06 1.04 2/55 25725
/proc/meminfo: memFree=830444/1022884 swapFree=0/0
[pid=25725] ppid=25724 vsize=103288 CPUtime=0.19
/proc/25725/stat : 25725 (aptitude) R 25724 25725 17863 34816 17863 4202496 11300 1708 0 0 17 2 0 0 20 0 1 0 29601131 105766912 11101 18446744073709551615 140075091308544 140075095615896 140737293168864 140737293160128 140075086031340 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25725/statm: 25822 11101 9889 1052 0 1159 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 103288

[startup+0.300274 s]
/proc/loadavg: 1.02 1.06 1.04 2/55 25725
/proc/meminfo: memFree=830444/1022884 swapFree=0/0
[pid=25725] ppid=25724 vsize=103432 CPUtime=0.29
/proc/25725/stat : 25725 (aptitude) R 25724 25725 17863 34816 17863 4202496 11427 1708 0 0 27 2 0 0 20 0 1 0 29601131 105914368 11220 18446744073709551615 140075091308544 140075095615896 140737293168864 140737293158640 140075086161890 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25725/statm: 25858 11220 9956 1052 0 1195 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 103432

[startup+0.700199 s]
/proc/loadavg: 1.02 1.06 1.04 2/55 25725
/proc/meminfo: memFree=830444/1022884 swapFree=0/0
[pid=25725] ppid=25724 vsize=123068 CPUtime=0.68
/proc/25725/stat : 25725 (aptitude) R 25724 25725 17863 34816 17863 4202496 17688 1708 0 0 64 4 0 0 20 0 1 0 29601131 126021632 15965 18446744073709551615 140075091308544 140075095615896 140737293168864 140737293158296 140075094233855 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25725/statm: 30767 15965 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.02 1.06 1.04 2/57 25730
/proc/meminfo: memFree=810340/1022884 swapFree=0/0
[pid=25725] ppid=25724 vsize=136048 CPUtime=1.47
/proc/25725/stat : 25725 (aptitude) R 25724 25725 17863 34816 17863 4202496 20641 1708 0 0 142 5 0 0 20 0 2 0 29601131 139313152 17560 18446744073709551615 140075091308544 140075095615896 140737293168864 140737293160136 140075093510015 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25725/statm: 34012 17560 10207 1052 0 9349 0
[pid=25725/tid=25730] ppid=25724 vsize=136048 CPUtime=0
/proc/25725/task/25730/stat : 25730 (aptitude) S 25724 25725 17863 34816 17863 4202560 4 1708 0 0 0 0 0 0 20 0 2 0 29601207 139313152 17560 18446744073709551615 140075091308544 140075095615896 140737293168864 140074978985984 140075060052692 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) 136048

[startup+3.10025 s]
/proc/loadavg: 1.02 1.06 1.04 2/57 25730
/proc/meminfo: memFree=800172/1022884 swapFree=0/0
[pid=25725] ppid=25724 vsize=137804 CPUtime=3.04
/proc/25725/stat : 25725 (aptitude) R 25724 25725 17863 34816 17863 4202496 21984 2206 0 0 295 9 0 0 20 0 2 0 29601131 141111296 17929 18446744073709551615 140075091308544 140075095615896 140737293168864 140737293155568 140075057613789 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 2 0 0
/proc/25725/statm: 34451 17929 10303 1052 0 9788 0
[pid=25725/tid=25730] ppid=25724 vsize=137804 CPUtime=0
/proc/25725/task/25730/stat : 25730 (aptitude) S 25724 25725 17863 34816 17863 4202560 6 2206 0 0 0 0 0 0 20 0 2 0 29601207 141111296 17929 18446744073709551615 140075091308544 140075095615896 140737293168864 140074978985984 140075060052692 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.04
Current children cumulated vsize (KiB) 137804

[startup+6.30024 s]
/proc/loadavg: 1.02 1.06 1.04 2/57 25731
/proc/meminfo: memFree=756524/1022884 swapFree=0/0
[pid=25725] ppid=25724 vsize=253132 CPUtime=6.23
/proc/25725/stat : 25725 (aptitude) S 25724 25725 17863 34816 17863 4202496 35199 2206 0 0 607 16 0 0 20 0 2 0 29601131 259207168 30606 18446744073709551615 140075091308544 140075095615896 140737293168864 140737293160624 140075060053579 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 2 0 0
/proc/25725/statm: 63283 30606 10359 1052 0 38620 0
[pid=25725/tid=25730] ppid=25724 vsize=253132 CPUtime=2.86
/proc/25725/task/25730/stat : 25730 (aptitude) R 25724 25725 17863 34816 17863 4202560 13214 2206 0 0 280 6 0 0 20 0 2 0 29601207 259207168 30606 18446744073709551615 140075091308544 140075095615896 140737293168864 140074978977304 140075091953970 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.23
Current children cumulated vsize (KiB) 253132

[startup+12.7002 s]
/proc/loadavg: 1.01 1.06 1.04 2/57 25731
/proc/meminfo: memFree=708660/1022884 swapFree=0/0
[pid=25725] ppid=25724 vsize=296956 CPUtime=12.6
/proc/25725/stat : 25725 (aptitude) S 25724 25725 17863 34816 17863 4202496 46331 2206 0 0 1240 20 0 0 20 0 2 0 29601131 304082944 41549 18446744073709551615 140075091308544 140075095615896 140737293168864 140737293160624 140075060053579 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 2 0 0
/proc/25725/statm: 74239 41549 10360 1052 0 49576 0
[pid=25725/tid=25730] ppid=25724 vsize=296956 CPUtime=9.23
/proc/25725/task/25730/stat : 25730 (aptitude) R 25724 25725 17863 34816 17863 4202560 24346 2206 0 0 912 11 0 0 20 0 2 0 29601207 304082944 41549 18446744073709551615 140075091308544 140075095615896 140737293168864 140074978977304 140075094016534 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.6
Current children cumulated vsize (KiB) 296956

[startup+25.5002 s]
/proc/loadavg: 1.01 1.06 1.04 2/57 25731
/proc/meminfo: memFree=632524/1022884 swapFree=0/0
[pid=25725] ppid=25724 vsize=370192 CPUtime=25.32
/proc/25725/stat : 25725 (aptitude) S 25724 25725 17863 34816 17863 4202496 64924 2206 0 0 2499 33 0 0 20 0 2 0 29601131 379076608 59866 18446744073709551615 140075091308544 140075095615896 140737293168864 140737293160624 140075060053579 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 2 0 0
/proc/25725/statm: 92548 59866 10360 1052 0 67885 0
[pid=25725/tid=25730] ppid=25724 vsize=370192 CPUtime=21.95
/proc/25725/task/25730/stat : 25730 (aptitude) R 25724 25725 17863 34816 17863 4202560 42939 2206 0 0 2171 24 0 0 20 0 2 0 29601207 379076608 59866 18446744073709551615 140075091308544 140075095615896 140737293168864 140074978977304 140075057613804 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 25.32
Current children cumulated vsize (KiB) 370192

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

[startup+25.6003 s]
/proc/loadavg: 1.01 1.06 1.04 2/57 25731
/proc/meminfo: memFree=632524/1022884 swapFree=0/0
[pid=25725] ppid=25724 vsize=370456 CPUtime=25.42
/proc/25725/stat : 25725 (aptitude) S 25724 25725 17863 34816 17863 4202496 64987 2206 0 0 2508 34 0 0 20 0 2 0 29601131 379346944 59929 18446744073709551615 140075091308544 140075095615896 140737293168864 140737293160624 140075060053579 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 2 0 0
/proc/25725/statm: 92614 59929 10360 1052 0 67951 0
[pid=25725/tid=25730] ppid=25724 vsize=370456 CPUtime=22.04
/proc/25725/task/25730/stat : 25730 (aptitude) R 25724 25725 17863 34816 17863 4202560 43002 2206 0 0 2180 24 0 0 20 0 2 0 29601207 379346944 59929 18446744073709551615 140075091308544 140075095615896 140737293168864 140074978977304 140075057617899 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 25.42
Current children cumulated vsize (KiB) 370456

[startup+27.2003 s]
/proc/loadavg: 1.01 1.06 1.04 2/57 25731
/proc/meminfo: memFree=625828/1022884 swapFree=0/0
[pid=25725] ppid=25724 vsize=378548 CPUtime=27.01
/proc/25725/stat : 25725 (aptitude) S 25724 25725 17863 34816 17863 4202496 67022 2206 0 0 2666 35 0 0 20 0 2 0 29601131 387633152 61953 18446744073709551615 140075091308544 140075095615896 140737293168864 140737293160624 140075060053579 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 2 0 0
/proc/25725/statm: 94637 61953 10360 1052 0 69974 0
[pid=25725/tid=25730] ppid=25724 vsize=378548 CPUtime=23.64
/proc/25725/task/25730/stat : 25730 (aptitude) R 25724 25725 17863 34816 17863 4202560 45037 2206 0 0 2338 26 0 0 20 0 2 0 29601207 387633152 61953 18446744073709551615 140075091308544 140075095615896 140737293168864 140074978977304 140075057617899 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 27.01
Current children cumulated vsize (KiB) 378548

[startup+28.0002 s]
/proc/loadavg: 1.01 1.06 1.04 2/57 25731
/proc/meminfo: memFree=621488/1022884 swapFree=0/0
[pid=25725] ppid=25724 vsize=381684 CPUtime=27.81
/proc/25725/stat : 25725 (aptitude) R 25724 25725 17863 34816 17863 4202496 68034 2206 0 0 2745 36 0 0 20 0 2 0 29601131 390844416 62911 18446744073709551615 140075091308544 140075095615896 140737293168864 140737293159000 140075048818824 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 2 0 0
/proc/25725/statm: 95421 62911 10409 1052 0 70751 0
[pid=25725/tid=25730] ppid=25724 vsize=381684 CPUtime=24.2
/proc/25725/task/25730/stat : 25730 (aptitude) S 25724 25725 17863 34816 17863 4202560 45838 2206 0 0 2394 26 0 0 20 0 2 0 29601207 390844416 62911 18446744073709551615 140075091308544 140075095615896 140737293168864 140074978985984 140075060052692 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0
Current children cumulated CPU time (s) 27.81
Current children cumulated vsize (KiB) 381684

[startup+28.4002 s]
/proc/loadavg: 1.01 1.06 1.04 2/57 25731
/proc/meminfo: memFree=621488/1022884 swapFree=0/0
[pid=25725] ppid=25724 vsize=381724 CPUtime=28.21
/proc/25725/stat : 25725 (aptitude) R 25724 25725 17863 34816 17863 4202496 70590 2206 0 0 2785 36 0 0 20 0 2 0 29601131 390885376 62909 18446744073709551615 140075091308544 140075095615896 140737293168864 140737293161064 140075093509915 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 2 0 0
/proc/25725/statm: 95431 62909 10410 1052 0 70761 0
[pid=25725/tid=25730] ppid=25724 vsize=381724 CPUtime=24.2
/proc/25725/task/25730/stat : 25730 (aptitude) S 25724 25725 17863 34816 17863 4202560 45838 2206 0 0 2394 26 0 0 20 0 2 0 29601207 390885376 62909 18446744073709551615 140075091308544 140075095615896 140737293168864 140074978985984 140075060052692 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0
Current children cumulated CPU time (s) 28.21
Current children cumulated vsize (KiB) 381724

[startup+28.8003 s]
/proc/loadavg: 1.01 1.06 1.04 2/57 25732
/proc/meminfo: memFree=618628/1022884 swapFree=0/0
[pid=25725] ppid=25724 vsize=193552 CPUtime=28.61
/proc/25725/stat : 25725 (aptitude) R 25724 25725 17863 34816 17863 4202496 71371 2705 0 0 2809 51 0 1 20 0 1 0 29601131 198197248 15903 18446744073709551615 140075091308544 140075095615896 140737293168864 140737293165944 140075057617968 0 134217728 4096 0 0 0 0 17 0 0 0 2 0 0
/proc/25725/statm: 48388 15903 1504 1052 0 32644 0
Current children cumulated CPU time (s) 28.61
Current children cumulated vsize (KiB) 193552

Child status: 0
Real time (s): 28.8161
CPU time (s): 28.6458
CPU user time (s): 28.1018
CPU system time (s): 0.544034
CPU usage (%): 99.409
Max. virtual memory (cumulated for all children) (KiB): 381724

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 28.1018
system time used= 0.544034
maximum resident set size= 252504
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 74175
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= 120
involuntary context switches= 530

runsolver used 0.048003 second user time and 0.088005 second system time

The end