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/8.runsolver.aptitude aptitude -s -y --without-recommends install tfm-arphic-gbsn00lp leksbot gtk-engines-pixmap egroupware-tts kde-i18n-is 

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.31 1.12 1.03 2/55 25041
/proc/meminfo: memFree=910424/1022884 swapFree=0/0
[pid=25041] ppid=25040 vsize=3152 CPUtime=0
/proc/25041/stat : 25041 (runsolver) R 25040 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29311072 3227648 33 18446744073709551615 134512640 134586868 4291747488 4291745536 4151997488 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/25041/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.201751 s]
/proc/loadavg: 1.31 1.12 1.03 2/55 25041
/proc/meminfo: memFree=910424/1022884 swapFree=0/0
[pid=25041] ppid=25040 vsize=23840 CPUtime=0
/proc/25041/stat : 25041 (aptitude) D 25040 25041 17863 34816 17863 4202496 143 0 11 0 0 0 0 0 20 0 1 0 29311072 24412160 68 18446744073709551615 140596928884736 140596933192088 140735565417232 140735565413944 140596926743310 0 0 0 0 0 0 0 17 0 0 0 19 0 0
/proc/25041/statm: 5960 68 45 1052 0 31 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 23840

[startup+0.300373 s]
/proc/loadavg: 1.31 1.12 1.03 2/55 25041
/proc/meminfo: memFree=910424/1022884 swapFree=0/0
[pid=25041] ppid=25040 vsize=36128 CPUtime=0
/proc/25041/stat : 25041 (aptitude) D 25040 25041 17863 34816 17863 4202496 163 0 19 0 0 0 0 0 20 0 1 0 29311072 36995072 92 18446744073709551615 140596928884736 140596933192088 140735565417232 140735565413656 140596926743942 0 0 0 0 0 0 0 17 0 0 0 29 0 0
/proc/25041/statm: 9032 92 58 1052 0 39 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 36128

[startup+0.400357 s]
/proc/loadavg: 1.31 1.12 1.03 2/55 25041
/proc/meminfo: memFree=910424/1022884 swapFree=0/0
[pid=25041] ppid=25040 vsize=54856 CPUtime=0
/proc/25041/stat : 25041 (aptitude) D 25040 25041 17863 34816 17863 4202496 291 0 31 0 0 0 0 0 20 0 1 0 29311072 56172544 223 18446744073709551615 140596928884736 140596933192088 140735565417232 140735565416440 140596926687965 0 0 0 0 0 0 0 17 0 0 0 38 0 0
/proc/25041/statm: 13714 223 153 1052 0 72 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 54856

[startup+0.70031 s]
/proc/loadavg: 1.31 1.12 1.03 2/55 25041
/proc/meminfo: memFree=910424/1022884 swapFree=0/0
[pid=25041] ppid=25040 vsize=54968 CPUtime=0.01
/proc/25041/stat : 25041 (aptitude) D 25040 25041 17863 34816 17863 4202496 1012 0 65 0 0 1 0 0 20 0 1 0 29311072 56287232 968 18446744073709551615 140596928884736 140596933192088 140735565417232 140735565413848 140596886728773 0 134217728 4096 0 0 0 0 17 0 0 0 67 0 0
/proc/25041/statm: 13742 968 808 1052 0 106 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 54968

[startup+1.50031 s]
/proc/loadavg: 1.31 1.12 1.03 1/56 25045
/proc/meminfo: memFree=895908/1022884 swapFree=0/0
[pid=25041] ppid=25040 vsize=103288 CPUtime=0.02
/proc/25041/stat : 25041 (aptitude) D 25040 25041 17863 34816 17863 4202496 3046 1704 168 4 0 2 0 0 20 0 1 0 29311072 105766912 3016 18446744073709551615 140596928884736 140596933192088 140735565417232 140735565408704 140596923934618 0 134217728 4096 0 0 0 0 17 0 0 0 141 0 0
/proc/25041/statm: 25822 3016 1804 1052 0 1159 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 103288

[startup+3.10033 s]
/proc/loadavg: 1.31 1.12 1.03 1/56 25045
/proc/meminfo: memFree=892560/1022884 swapFree=0/0
[pid=25041] ppid=25040 vsize=103288 CPUtime=0.3
/proc/25041/stat : 25041 (aptitude) D 25040 25041 17863 34816 17863 4202496 10939 1704 381 4 26 4 0 0 20 0 1 0 29311072 105766912 11121 18446744073709551615 140596928884736 140596933192088 140735565417232 140735565408744 140596897640816 0 134217728 4096 0 0 0 0 17 0 0 0 275 0 0
/proc/25041/statm: 25822 11121 9902 1052 0 1159 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 103288
heavy processes:

[startup+6.30022 s]
/proc/loadavg: 1.29 1.12 1.03 2/57 25046
/proc/meminfo: memFree=743628/1022884 swapFree=0/0
[pid=25041] ppid=25040 vsize=137796 CPUtime=2.54
/proc/25041/stat : 25041 (aptitude) R 25040 25041 17863 34816 17863 4202496 21559 2201 398 5 237 16 0 1 20 0 2 0 29311072 141103104 17927 18446744073709551615 140596928884736 140596933192088 140735565417232 140735565409256 140596895197298 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 368 0 0
/proc/25041/statm: 34449 17927 10303 1052 0 9786 0
[pid=25041/tid=25046] ppid=25040 vsize=137796 CPUtime=0.01
/proc/25041/task/25046/stat : 25046 (aptitude) S 25040 25041 17863 34816 17863 4202560 6 2201 0 5 0 0 0 1 20 0 2 0 29311515 141103104 17927 18446744073709551615 140596928884736 140596933192088 140735565417232 140596816562176 140596897628884 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 2.54
Current children cumulated vsize (KiB) 137796
heavy processes:

[startup+12.7002 s]
/proc/loadavg: 1.26 1.12 1.03 2/57 25047
/proc/meminfo: memFree=673940/1022884 swapFree=0/0
[pid=25041] ppid=25040 vsize=275196 CPUtime=8.91
/proc/25041/stat : 25041 (aptitude) S 25040 25041 17863 34816 17863 4202496 40351 2201 398 5 868 22 0 1 20 0 2 0 29311072 281800704 36140 18446744073709551615 140596928884736 140596933192088 140735565417232 140735565408992 140596897629771 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 368 0 0
/proc/25041/statm: 68799 36140 10359 1052 0 44136 0
[pid=25041/tid=25046] ppid=25040 vsize=275196 CPUtime=5.53
/proc/25041/task/25046/stat : 25046 (aptitude) R 25040 25041 17863 34816 17863 4202560 18767 2201 0 5 547 5 0 1 20 0 2 0 29311515 281800704 36140 18446744073709551615 140596928884736 140596933192088 140735565417232 140596816555704 140596929530162 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 8.91
Current children cumulated vsize (KiB) 275196
heavy processes:

[startup+25.5032 s]
/proc/loadavg: 1.20 1.11 1.03 2/57 25047
/proc/meminfo: memFree=583420/1022884 swapFree=0/0
[pid=25041] ppid=25040 vsize=362208 CPUtime=21.65
/proc/25041/stat : 25041 (aptitude) S 25040 25041 17863 34816 17863 4202496 62465 2201 398 5 2128 36 0 1 20 0 2 0 29311072 370900992 57876 18446744073709551615 140596928884736 140596933192088 140735565417232 140735565408992 140596897629771 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 368 0 0
/proc/25041/statm: 90552 57876 10360 1052 0 65889 0
[pid=25041/tid=25046] ppid=25040 vsize=362208 CPUtime=18.27
/proc/25041/task/25046/stat : 25046 (aptitude) R 25040 25041 17863 34816 17863 4202560 40881 2201 0 5 1806 20 0 1 20 0 2 0 29311515 370900992 57876 18446744073709551615 140596928884736 140596933192088 140735565417232 140596816555104 140596931531296 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 21.65
Current children cumulated vsize (KiB) 362208

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

[startup+25.7002 s]
/proc/loadavg: 1.20 1.11 1.03 2/57 25047
/proc/meminfo: memFree=583420/1022884 swapFree=0/0
[pid=25041] ppid=25040 vsize=363596 CPUtime=21.84
/proc/25041/stat : 25041 (aptitude) S 25040 25041 17863 34816 17863 4202496 62790 2201 398 5 2147 36 0 1 20 0 2 0 29311072 372322304 58201 18446744073709551615 140596928884736 140596933192088 140735565417232 140735565408992 140596897629771 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 368 0 0
/proc/25041/statm: 90899 58201 10360 1052 0 66236 0
[pid=25041/tid=25046] ppid=25040 vsize=363596 CPUtime=18.47
/proc/25041/task/25046/stat : 25046 (aptitude) R 25040 25041 17863 34816 17863 4202560 41206 2201 0 5 1826 20 0 1 20 0 2 0 29311515 372322304 58201 18446744073709551615 140596928884736 140596933192088 140735565417232 140596816553448 140596931247707 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 21.84
Current children cumulated vsize (KiB) 363596

[startup+38.5002 s]
/proc/loadavg: 1.17 1.11 1.03 2/57 25047
/proc/meminfo: memFree=514724/1022884 swapFree=0/0
[pid=25041] ppid=25040 vsize=434104 CPUtime=34.58
/proc/25041/stat : 25041 (aptitude) S 25040 25041 17863 34816 17863 4202496 80442 2201 398 5 3413 44 0 1 20 0 2 0 29311072 444522496 75826 18446744073709551615 140596928884736 140596933192088 140735565417232 140735565408992 140596897629771 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 368 0 0
/proc/25041/statm: 108526 75826 10360 1052 0 83863 0
[pid=25041/tid=25046] ppid=25040 vsize=434104 CPUtime=31.21
/proc/25041/task/25046/stat : 25046 (aptitude) R 25040 25041 17863 34816 17863 4202560 58858 2201 0 5 3092 28 0 1 20 0 2 0 29311515 444522496 75826 18446744073709551615 140596928884736 140596933192088 140735565417232 140596816553496 140596931629523 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 34.58
Current children cumulated vsize (KiB) 434104

[startup+41.7002 s]
/proc/loadavg: 1.24 1.12 1.03 2/57 25047
/proc/meminfo: memFree=498108/1022884 swapFree=0/0
[pid=25041] ppid=25040 vsize=450480 CPUtime=37.77
/proc/25041/stat : 25041 (aptitude) S 25040 25041 17863 34816 17863 4202496 84561 2201 398 5 3731 45 0 1 20 0 2 0 29311072 461291520 79927 18446744073709551615 140596928884736 140596933192088 140735565417232 140735565408992 140596897629771 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 368 0 0
/proc/25041/statm: 112620 79927 10360 1052 0 87957 0
[pid=25041/tid=25046] ppid=25040 vsize=450480 CPUtime=34.4
/proc/25041/task/25046/stat : 25046 (aptitude) R 25040 25041 17863 34816 17863 4202560 62977 2201 0 5 3410 29 0 1 20 0 2 0 29311515 461291520 79927 18446744073709551615 140596928884736 140596933192088 140735565417232 140596816553448 140596886380334 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 37.77
Current children cumulated vsize (KiB) 450480

[startup+43.3002 s]
/proc/loadavg: 1.24 1.12 1.03 2/57 25047
/proc/meminfo: memFree=488312/1022884 swapFree=0/0
[pid=25041] ppid=25040 vsize=457636 CPUtime=39.36
/proc/25041/stat : 25041 (aptitude) S 25040 25041 17863 34816 17863 4202496 86338 2201 398 5 3888 47 0 1 20 0 2 0 29311072 468619264 81704 18446744073709551615 140596928884736 140596933192088 140735565417232 140735565408992 140596897629771 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 368 0 0
/proc/25041/statm: 114409 81704 10360 1052 0 89746 0
[pid=25041/tid=25046] ppid=25040 vsize=457636 CPUtime=35.99
/proc/25041/task/25046/stat : 25046 (aptitude) R 25040 25041 17863 34816 17863 4202560 64754 2201 0 5 3567 31 0 1 20 0 2 0 29311515 468619264 81704 18446744073709551615 140596928884736 140596933192088 140735565417232 140596816555704 140596930234880 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 39.36
Current children cumulated vsize (KiB) 457636

[startup+44.9002 s]
/proc/loadavg: 1.22 1.12 1.03 2/57 25047
/proc/meminfo: memFree=483476/1022884 swapFree=0/0
[pid=25041] ppid=25040 vsize=463780 CPUtime=40.9
/proc/25041/stat : 25041 (aptitude) R 25040 25041 17863 34816 17863 4202496 88084 2201 403 5 4042 47 0 1 20 0 2 0 29311072 474910720 83400 18446744073709551615 140596928884736 140596933192088 140735565417232 140735565407368 140596929652023 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 374 0 0
/proc/25041/statm: 115945 83400 10408 1052 0 91275 0
[pid=25041/tid=25046] ppid=25040 vsize=463780 CPUtime=37.29
/proc/25041/task/25046/stat : 25046 (aptitude) S 25040 25041 17863 34816 17863 4202560 66292 2201 0 5 3697 31 0 1 20 0 2 0 29311515 474910720 83400 18446744073709551615 140596928884736 140596933192088 140735565417232 140596816562176 140596897628884 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 40.9
Current children cumulated vsize (KiB) 463780

[startup+45.7002 s]
/proc/loadavg: 1.22 1.12 1.03 2/57 25047
/proc/meminfo: memFree=480128/1022884 swapFree=0/0
[pid=25041] ppid=25040 vsize=463812 CPUtime=41.69
/proc/25041/stat : 25041 (aptitude) R 25040 25041 17863 34816 17863 4202496 90740 2201 403 5 4120 48 0 1 20 0 2 0 29311072 474943488 83471 18446744073709551615 140596928884736 140596933192088 140735565417232 140735565409048 140596923782456 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 374 0 0
/proc/25041/statm: 115953 83471 10409 1052 0 91283 0
[pid=25041/tid=25046] ppid=25040 vsize=463812 CPUtime=37.29
/proc/25041/task/25046/stat : 25046 (aptitude) S 25040 25041 17863 34816 17863 4202560 66292 2201 0 5 3697 31 0 1 20 0 2 0 29311515 474943488 83471 18446744073709551615 140596928884736 140596933192088 140735565417232 140596816562176 140596897628884 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 41.69
Current children cumulated vsize (KiB) 463812

[startup+45.9002 s]
/proc/loadavg: 1.22 1.12 1.03 2/57 25047
/proc/meminfo: memFree=480128/1022884 swapFree=0/0
[pid=25041] ppid=25040 vsize=463812 CPUtime=41.9
/proc/25041/stat : 25041 (aptitude) R 25040 25041 17863 34816 17863 4202496 91050 2699 403 5 4130 58 0 2 20 0 2 0 29311072 474943488 83612 18446744073709551615 140596928884736 140596933192088 140735565417232 140735565409208 140596886394976 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 374 0 0
/proc/25041/statm: 115953 83612 10409 1052 0 91283 0
[pid=25041/tid=25046] ppid=25040 vsize=463812 CPUtime=37.3
/proc/25041/task/25046/stat : 25046 (aptitude) S 25040 25041 17863 34816 17863 4202560 66292 2699 0 5 3697 31 0 2 20 0 2 0 29311515 474943488 83612 18446744073709551615 140596928884736 140596933192088 140735565417232 140596816562176 140596897628884 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 41.9
Current children cumulated vsize (KiB) 463812

[startup+46.0007 s]
/proc/loadavg: 1.22 1.12 1.03 2/57 25047
/proc/meminfo: memFree=480128/1022884 swapFree=0/0
[pid=25041] ppid=25040 vsize=195564 CPUtime=42
/proc/25041/stat : 25041 (aptitude) R 25040 25041 17863 34816 17863 4202496 91490 2699 403 5 4132 66 0 2 20 0 1 0 29311072 200257536 13554 18446744073709551615 140596928884736 140596933192088 140735565417232 140735565416792 140596886750698 0 134217728 4096 0 0 0 0 17 0 0 0 374 0 0
/proc/25041/statm: 48891 13554 1508 1052 0 33147 0
Current children cumulated CPU time (s) 42
Current children cumulated vsize (KiB) 195564

Child status: 0
Real time (s): 46.0318
CPU time (s): 42.0306
CPU user time (s): 41.3306
CPU system time (s): 0.700043
CPU usage (%): 91.3078
Max. virtual memory (cumulated for all children) (KiB): 463812

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 41.3306
system time used= 0.700043
maximum resident set size= 334448
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 94254
page faults= 410
swaps= 0
block input operations= 274424
block output operations= 160
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2756
involuntary context switches= 768

runsolver used 0.068004 second user time and 0.152009 second system time

The end