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/logs/37.runsolver.aptitude aptitude -s -y --without-recommends install python-uncertainities libcfitsio2 contact-lookup-applet python-imaging-doc xfce4 

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.08 1.04 0.91 2/55 21164
/proc/meminfo: memFree=906236/1022884 swapFree=0/0
[pid=21164] ppid=21163 vsize=3152 CPUtime=0
/proc/21164/stat : 21164 (runsolver) R 21163 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28391034 3227648 33 18446744073709551615 134512640 134586868 4290790880 4290788928 4151252016 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/21164/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.165405 s]
/proc/loadavg: 1.08 1.04 0.91 2/55 21164
/proc/meminfo: memFree=906236/1022884 swapFree=0/0
[pid=21164] ppid=21163 vsize=89152 CPUtime=0.15
/proc/21164/stat : 21164 (aptitude) R 21163 21164 17863 34816 17863 4202496 7777 1709 0 0 13 2 0 0 20 0 1 0 28391034 91291648 7576 18446744073709551615 139877917728768 139877922036120 140735980549840 140735980541104 139877913129009 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21164/statm: 22288 7576 6665 1052 0 858 0
Current children cumulated CPU time (s) 0.15
Current children cumulated vsize (KiB) 89152

[startup+0.200269 s]
/proc/loadavg: 1.08 1.04 0.91 2/55 21164
/proc/meminfo: memFree=906236/1022884 swapFree=0/0
[pid=21164] ppid=21163 vsize=96860 CPUtime=0.18
/proc/21164/stat : 21164 (aptitude) R 21163 21164 17863 34816 17863 4202496 9803 1709 0 0 16 2 0 0 20 0 1 0 28391034 99184640 9594 18446744073709551615 139877917728768 139877922036120 140735980549840 140735980541488 139877884038123 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21164/statm: 24215 9594 6731 1052 0 2785 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 96860

[startup+0.300258 s]
/proc/loadavg: 1.08 1.04 0.91 2/55 21164
/proc/meminfo: memFree=906236/1022884 swapFree=0/0
[pid=21164] ppid=21163 vsize=101864 CPUtime=0.29
/proc/21164/stat : 21164 (aptitude) R 21163 21164 17863 34816 17863 4202496 11710 1709 0 0 24 5 0 0 20 0 1 0 28391034 104308736 10756 18446744073709551615 139877917728768 139877922036120 140735980549840 140735980539272 139877912629112 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21164/statm: 25466 10756 6746 1052 0 4036 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 101864

[startup+0.700188 s]
/proc/loadavg: 1.08 1.04 0.91 2/55 21164
/proc/meminfo: memFree=906236/1022884 swapFree=0/0
[pid=21164] ppid=21163 vsize=114224 CPUtime=0.69
/proc/21164/stat : 21164 (aptitude) R 21163 21164 17863 34816 17863 4202496 13733 1709 0 0 63 6 0 0 20 0 2 0 28391034 116965376 12105 18446744073709551615 139877917728768 139877922036120 140735980549840 140735980541112 139877919930084 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21164/statm: 28556 12105 6977 1052 0 7126 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 114224

[startup+1.50023 s]
/proc/loadavg: 1.08 1.04 0.91 2/57 21169
/proc/meminfo: memFree=885396/1022884 swapFree=0/0
[pid=21164] ppid=21163 vsize=115476 CPUtime=1.49
/proc/21164/stat : 21164 (aptitude) R 21163 21164 17863 34816 17863 4202496 14573 2208 0 0 140 8 1 0 20 0 2 0 28391034 118247424 12367 18446744073709551615 139877917728768 139877922036120 140735980549840 140735980541864 139877913128497 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21164/statm: 28869 12367 7073 1052 0 7439 0
[pid=21164/tid=21169] ppid=21163 vsize=115476 CPUtime=0.01
/proc/21164/task/21169/stat : 21169 (aptitude) S 21163 21164 17863 34816 17863 4202560 6 2208 0 0 0 0 1 0 20 0 2 0 28391074 118247424 12367 18446744073709551615 139877917728768 139877922036120 140735980549840 139877821134848 139877886472916 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 115476

[startup+3.10024 s]
/proc/loadavg: 1.07 1.04 0.91 2/57 21170
/proc/meminfo: memFree=876840/1022884 swapFree=0/0
[pid=21164] ppid=21163 vsize=138980 CPUtime=3.08
/proc/21164/stat : 21164 (aptitude) S 21163 21164 17863 34816 17863 4202496 21431 2208 0 0 298 9 1 0 20 0 2 0 28391034 142315520 18462 18446744073709551615 139877917728768 139877922036120 140735980549840 140735980541600 139877886473803 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21164/statm: 34745 18462 7129 1052 0 13315 0
[pid=21164/tid=21169] ppid=21163 vsize=138980 CPUtime=1.18
/proc/21164/task/21169/stat : 21169 (aptitude) R 21163 21164 17863 34816 17863 4202560 6777 2208 0 0 116 1 1 0 20 0 2 0 28391074 142315520 18462 18446744073709551615 139877917728768 139877922036120 140735980549840 139877821126216 139877875239048 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 138980

[startup+6.30024 s]
/proc/loadavg: 1.07 1.04 0.91 2/57 21170
/proc/meminfo: memFree=828232/1022884 swapFree=0/0
[pid=21164] ppid=21163 vsize=246532 CPUtime=6.27
/proc/21164/stat : 21164 (aptitude) S 21163 21164 17863 34816 17863 4202496 31952 2208 0 0 612 14 1 0 20 0 2 0 28391034 252448768 28975 18446744073709551615 139877917728768 139877922036120 140735980549840 140735980541600 139877886473803 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21164/statm: 61633 28975 7129 1052 0 40203 0
[pid=21164/tid=21169] ppid=21163 vsize=246532 CPUtime=4.37
/proc/21164/task/21169/stat : 21169 (aptitude) R 21163 21164 17863 34816 17863 4202560 17297 2208 0 0 430 6 1 0 20 0 2 0 28391074 252448768 28975 18446744073709551615 139877917728768 139877922036120 140735980549840 139877821128280 139877920375066 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.27
Current children cumulated vsize (KiB) 246532

[startup+12.7002 s]
/proc/loadavg: 1.06 1.04 0.91 2/57 21170
/proc/meminfo: memFree=767844/1022884 swapFree=0/0
[pid=21164] ppid=21163 vsize=300616 CPUtime=12.63
/proc/21164/stat : 21164 (aptitude) S 21163 21164 17863 34816 17863 4202496 45472 2208 0 0 1241 21 1 0 20 0 2 0 28391034 307830784 42468 18446744073709551615 139877917728768 139877922036120 140735980549840 140735980541600 139877886473803 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21164/statm: 75154 42468 7129 1052 0 53724 0
[pid=21164/tid=21169] ppid=21163 vsize=300616 CPUtime=10.73
/proc/21164/task/21169/stat : 21169 (aptitude) R 21163 21164 17863 34816 17863 4202560 30817 2208 0 0 1059 13 1 0 20 0 2 0 28391074 307830784 42468 18446744073709551615 139877917728768 139877922036120 140735980549840 139877821128376 139877921153380 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.63
Current children cumulated vsize (KiB) 300616

[startup+25.5003 s]
/proc/loadavg: 1.05 1.04 0.91 2/57 21170
/proc/meminfo: memFree=702744/1022884 swapFree=0/0
[pid=21164] ppid=21163 vsize=363124 CPUtime=25.37
/proc/21164/stat : 21164 (aptitude) S 21163 21164 17863 34816 17863 4202496 61272 2208 0 0 2506 30 1 0 20 0 2 0 28391034 371838976 58079 18446744073709551615 139877917728768 139877922036120 140735980549840 140735980541600 139877886473803 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21164/statm: 90781 58079 7129 1052 0 69351 0
[pid=21164/tid=21169] ppid=21163 vsize=363124 CPUtime=23.47
/proc/21164/task/21169/stat : 21169 (aptitude) R 21163 21164 17863 34816 17863 4202560 46617 2208 0 0 2324 22 1 0 20 0 2 0 28391074 371838976 58079 18446744073709551615 139877917728768 139877922036120 140735980549840 139877821128376 139877918374194 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.37
Current children cumulated vsize (KiB) 363124

[startup+51.1003 s]
/proc/loadavg: 1.16 1.06 0.93 2/57 21394
/proc/meminfo: memFree=524576/1022884 swapFree=0/0
[pid=21164] ppid=21163 vsize=458120 CPUtime=47.89
/proc/21164/stat : 21164 (aptitude) S 21163 21164 17863 34816 17863 4202496 85108 2208 0 0 4742 46 1 0 20 0 2 0 28391034 469114880 81873 18446744073709551615 139877917728768 139877922036120 140735980549840 140735980541600 139877886473803 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21164/statm: 114530 81873 7143 1052 0 93100 0
[pid=21164/tid=21169] ppid=21163 vsize=458120 CPUtime=46
/proc/21164/task/21169/stat : 21169 (aptitude) R 21163 21164 17863 34816 17863 4202560 70446 2208 0 0 4560 39 1 0 20 0 2 0 28391074 469114880 81873 18446744073709551615 139877917728768 139877922036120 140735980549840 139877821126120 139877883661982 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 47.89
Current children cumulated vsize (KiB) 458120

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

[startup+51.2004 s]
/proc/loadavg: 1.16 1.06 0.93 2/57 21394
/proc/meminfo: memFree=524576/1022884 swapFree=0/0
[pid=21164] ppid=21163 vsize=458648 CPUtime=47.99
/proc/21164/stat : 21164 (aptitude) S 21163 21164 17863 34816 17863 4202496 85222 2208 0 0 4752 46 1 0 20 0 2 0 28391034 469655552 81987 18446744073709551615 139877917728768 139877922036120 140735980549840 140735980541600 139877886473803 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21164/statm: 114662 81987 7143 1052 0 93232 0
[pid=21164/tid=21169] ppid=21163 vsize=458648 CPUtime=46.1
/proc/21164/task/21169/stat : 21169 (aptitude) R 21163 21164 17863 34816 17863 4202560 70560 2208 0 0 4570 39 1 0 20 0 2 0 28391074 469655552 81987 18446744073709551615 139877917728768 139877922036120 140735980549840 139877821126120 139877875239048 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 47.99
Current children cumulated vsize (KiB) 458648

[startup+52.8003 s]
/proc/loadavg: 1.14 1.06 0.93 2/57 21394
/proc/meminfo: memFree=515524/1022884 swapFree=0/0
[pid=21164] ppid=21163 vsize=465716 CPUtime=49.6
/proc/21164/stat : 21164 (aptitude) S 21163 21164 17863 34816 17863 4202496 86922 2208 0 0 4911 48 1 0 20 0 2 0 28391034 476893184 83684 18446744073709551615 139877917728768 139877922036120 140735980549840 140735980541600 139877886473803 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21164/statm: 116429 83684 7143 1052 0 94999 0
[pid=21164/tid=21169] ppid=21163 vsize=465716 CPUtime=47.69
/proc/21164/task/21169/stat : 21169 (aptitude) R 21163 21164 17863 34816 17863 4202560 72260 2208 0 0 4728 40 1 0 20 0 2 0 28391074 476893184 83684 18446744073709551615 139877917728768 139877922036120 140735980549840 139877821126248 139877921157432 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 49.6
Current children cumulated vsize (KiB) 465716

[startup+53.6002 s]
/proc/loadavg: 1.14 1.06 0.93 2/57 21394
/proc/meminfo: memFree=515524/1022884 swapFree=0/0
[pid=21164] ppid=21163 vsize=468252 CPUtime=50.38
/proc/21164/stat : 21164 (aptitude) R 21163 21164 17863 34816 17863 4202496 87913 2208 0 0 4989 48 1 0 20 0 2 0 28391034 479490048 84545 18446744073709551615 139877917728768 139877922036120 140735980549840 140735980539976 139877921159659 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21164/statm: 117063 84545 7191 1052 0 95626 0
[pid=21164/tid=21169] ppid=21163 vsize=468252 CPUtime=48.18
/proc/21164/task/21169/stat : 21169 (aptitude) S 21163 21164 17863 34816 17863 4202560 72904 2208 0 0 4777 40 1 0 20 0 2 0 28391074 479490048 84545 18446744073709551615 139877917728768 139877922036120 140735980549840 139877821134848 139877886472916 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 50.38
Current children cumulated vsize (KiB) 468252

[startup+54.0031 s]
/proc/loadavg: 1.14 1.06 0.93 2/57 21394
/proc/meminfo: memFree=511804/1022884 swapFree=0/0
[pid=21164] ppid=21163 vsize=468252 CPUtime=50.78
/proc/21164/stat : 21164 (aptitude) R 21163 21164 17863 34816 17863 4202496 87914 2208 0 0 5029 48 1 0 20 0 2 0 28391034 479490048 84546 18446744073709551615 139877917728768 139877922036120 140735980549840 140735980539976 139877920321616 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21164/statm: 117063 84546 7191 1052 0 95626 0
[pid=21164/tid=21169] ppid=21163 vsize=468252 CPUtime=48.18
/proc/21164/task/21169/stat : 21169 (aptitude) S 21163 21164 17863 34816 17863 4202560 72904 2208 0 0 4777 40 1 0 20 0 2 0 28391074 479490048 84546 18446744073709551615 139877917728768 139877922036120 140735980549840 139877821134848 139877886472916 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 50.78
Current children cumulated vsize (KiB) 468252

[startup+54.4002 s]
/proc/loadavg: 1.14 1.06 0.93 2/57 21394
/proc/meminfo: memFree=511804/1022884 swapFree=0/0
[pid=21164] ppid=21163 vsize=468332 CPUtime=51.19
/proc/21164/stat : 21164 (aptitude) R 21163 21164 17863 34816 17863 4202496 89877 2208 0 0 5069 49 1 0 20 0 2 0 28391034 479571968 84570 18446744073709551615 139877917728768 139877922036120 140735980549840 140735980541656 139877912626488 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21164/statm: 117083 84570 7192 1052 0 95646 0
[pid=21164/tid=21169] ppid=21163 vsize=468332 CPUtime=48.18
/proc/21164/task/21169/stat : 21169 (aptitude) S 21163 21164 17863 34816 17863 4202560 72904 2208 0 0 4777 40 1 0 20 0 2 0 28391074 479571968 84570 18446744073709551615 139877917728768 139877922036120 140735980549840 139877821134848 139877886472916 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 51.19
Current children cumulated vsize (KiB) 468332

[startup+54.5002 s]
/proc/loadavg: 1.14 1.06 0.93 2/57 21394
/proc/meminfo: memFree=511804/1022884 swapFree=0/0
[pid=21164] ppid=21163 vsize=468332 CPUtime=51.28
/proc/21164/stat : 21164 (aptitude) R 21163 21164 17863 34816 17863 4202496 89987 2708 0 0 5070 56 1 1 20 0 2 0 28391034 479571968 84566 18446744073709551615 139877917728768 139877922036120 140735980549840 140735980541816 139877875572805 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21164/statm: 117083 84566 7192 1052 0 95646 0
[pid=21164/tid=21169] ppid=21163 vsize=468332 CPUtime=48.19
/proc/21164/task/21169/stat : 21169 (aptitude) S 21163 21164 17863 34816 17863 4202560 72904 2708 0 0 4777 40 1 1 20 0 2 0 28391074 479571968 84566 18446744073709551615 139877917728768 139877922036120 140735980549840 139877821134848 139877886472916 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 51.28
Current children cumulated vsize (KiB) 468332

Child status: 0
Real time (s): 54.595
CPU time (s): 51.3952
CPU user time (s): 50.7272
CPU system time (s): 0.668041
CPU usage (%): 94.139
Max. virtual memory (cumulated for all children) (KiB): 468332

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 50.7272
system time used= 0.668041
maximum resident set size= 338668
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 93429
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= 169
involuntary context switches= 4413

runsolver used 0.088005 second user time and 0.16001 second system time

The end