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/95.runsolver.aptitude aptitude -s -y --without-recommends install mozilla-cascades zip fte-xwindow lm-sensors-2.4.27-3-k7 libaudio-dev 

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.07 1.12 1.09 2/55 26523
/proc/meminfo: memFree=771944/1022884 swapFree=0/0
[pid=26523] ppid=26522 vsize=3152 CPUtime=0
/proc/26523/stat : 26523 (runsolver) R 26522 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29854772 3227648 32 18446744073709551615 134512640 134586868 4290785440 4290783488 4152161328 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/26523/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.136125 s]
/proc/loadavg: 1.07 1.12 1.09 2/55 26523
/proc/meminfo: memFree=771944/1022884 swapFree=0/0
[pid=26523] ppid=26522 vsize=103288 CPUtime=0.13
/proc/26523/stat : 26523 (aptitude) R 26522 26523 17863 34816 17863 4202496 11251 1711 0 0 10 2 1 0 20 0 1 0 29854772 105766912 11052 18446744073709551615 140492387160064 140492391467416 140735104004608 140735103995872 140492344347308 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26523/statm: 25822 11052 9840 1052 0 1159 0
Current children cumulated CPU time (s) 0.13
Current children cumulated vsize (KiB) 103288

[startup+0.200283 s]
/proc/loadavg: 1.07 1.12 1.09 2/55 26523
/proc/meminfo: memFree=771944/1022884 swapFree=0/0
[pid=26523] ppid=26522 vsize=103288 CPUtime=0.19
/proc/26523/stat : 26523 (aptitude) R 26522 26523 17863 34816 17863 4202496 11300 1711 0 0 16 2 1 0 20 0 1 0 29854772 105766912 11101 18446744073709551615 140492387160064 140492391467416 140735104004608 140735103995872 140492382001646 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26523/statm: 25822 11101 9889 1052 0 1159 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 103288

[startup+0.300268 s]
/proc/loadavg: 1.07 1.12 1.09 2/55 26523
/proc/meminfo: memFree=771944/1022884 swapFree=0/0
[pid=26523] ppid=26522 vsize=103432 CPUtime=0.29
/proc/26523/stat : 26523 (aptitude) R 26522 26523 17863 34816 17863 4202496 11427 1711 0 0 26 2 1 0 20 0 1 0 29854772 105914368 11220 18446744073709551615 140492387160064 140492391467416 140735104004608 140735103994384 140492382013410 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26523/statm: 25858 11220 9956 1052 0 1195 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 103432

[startup+0.700201 s]
/proc/loadavg: 1.07 1.12 1.09 2/55 26523
/proc/meminfo: memFree=771944/1022884 swapFree=0/0
[pid=26523] ppid=26522 vsize=123068 CPUtime=0.69
/proc/26523/stat : 26523 (aptitude) R 26522 26523 17863 34816 17863 4202496 17689 1711 0 0 62 6 1 0 20 0 1 0 29854772 126021632 15965 18446744073709551615 140492387160064 140492391467416 140735104004608 140735103994040 140492390085592 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26523/statm: 30767 15965 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 123068

[startup+1.50025 s]
/proc/loadavg: 1.07 1.12 1.09 2/57 26528
/proc/meminfo: memFree=751972/1022884 swapFree=0/0
[pid=26523] ppid=26522 vsize=136044 CPUtime=1.49
/proc/26523/stat : 26523 (aptitude) R 26522 26523 17863 34816 17863 4202496 20639 1711 0 0 140 8 1 0 20 0 2 0 29854772 139309056 17558 18446744073709551615 140492387160064 140492391467416 140735104004608 140735103995880 140492344670344 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26523/statm: 34011 17558 10207 1052 0 9348 0
[pid=26523/tid=26528] ppid=26522 vsize=136044 CPUtime=0.01
/proc/26523/task/26528/stat : 26528 (aptitude) S 26522 26523 17863 34816 17863 4202560 4 1711 0 0 0 0 1 0 20 0 2 0 29854849 139309056 17558 18446744073709551615 140492387160064 140492391467416 140735104004608 140492274837504 140492355904212 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) 136044

[startup+3.10025 s]
/proc/loadavg: 1.07 1.12 1.09 2/57 26528
/proc/meminfo: memFree=741804/1022884 swapFree=0/0
[pid=26523] ppid=26522 vsize=137796 CPUtime=3.08
/proc/26523/stat : 26523 (aptitude) R 26522 26523 17863 34816 17863 4202496 21985 2209 0 0 293 14 1 0 20 0 2 0 29854772 141103104 17932 18446744073709551615 140492387160064 140492391467416 140735104004608 140735103991312 140492389867968 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26523/statm: 34449 17932 10303 1052 0 9786 0
[pid=26523/tid=26528] ppid=26522 vsize=137796 CPUtime=0.01
/proc/26523/task/26528/stat : 26528 (aptitude) S 26522 26523 17863 34816 17863 4202560 6 2209 0 0 0 0 1 0 20 0 2 0 29854849 141103104 17932 18446744073709551615 140492387160064 140492391467416 140735104004608 140492274837504 140492355904212 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) 137796

[startup+6.30024 s]
/proc/loadavg: 1.07 1.12 1.09 2/57 26529
/proc/meminfo: memFree=699768/1022884 swapFree=0/0
[pid=26523] ppid=26522 vsize=185744 CPUtime=6.26
/proc/26523/stat : 26523 (aptitude) S 26522 26523 17863 34816 17863 4202496 34767 2209 0 0 606 19 1 0 20 0 2 0 29854772 190201856 30169 18446744073709551615 140492387160064 140492391467416 140735104004608 140735103996368 140492355905099 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26523/statm: 46436 30169 10359 1052 0 21773 0
[pid=26523/tid=26528] ppid=26522 vsize=185744 CPUtime=2.86
/proc/26523/task/26528/stat : 26528 (aptitude) R 26522 26523 17863 34816 17863 4202560 12782 2209 0 0 280 5 1 0 20 0 2 0 29854849 190201856 30169 18446744073709551615 140492387160064 140492391467416 140735104004608 140492274828824 140492344670304 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.26
Current children cumulated vsize (KiB) 185744

[startup+12.7002 s]
/proc/loadavg: 1.06 1.11 1.08 2/57 26529
/proc/meminfo: memFree=651904/1022884 swapFree=0/0
[pid=26523] ppid=26522 vsize=296964 CPUtime=12.63
/proc/26523/stat : 26523 (aptitude) S 26522 26523 17863 34816 17863 4202496 46548 2209 0 0 1236 26 1 0 20 0 2 0 29854772 304091136 41565 18446744073709551615 140492387160064 140492391467416 140735104004608 140735103996368 140492355905099 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26523/statm: 74241 41565 10360 1052 0 49578 0
[pid=26523/tid=26528] ppid=26522 vsize=296964 CPUtime=9.23
/proc/26523/task/26528/stat : 26528 (aptitude) R 26522 26523 17863 34816 17863 4202560 24562 2209 0 0 911 11 1 0 20 0 2 0 29854849 304091136 41565 18446744073709551615 140492387160064 140492391467416 140735104004608 140492274828952 140492389361435 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) 296964

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

[startup+12.8003 s]
/proc/loadavg: 1.06 1.11 1.08 2/57 26529
/proc/meminfo: memFree=651904/1022884 swapFree=0/0
[pid=26523] ppid=26522 vsize=297228 CPUtime=12.73
/proc/26523/stat : 26523 (aptitude) S 26522 26523 17863 34816 17863 4202496 46606 2209 0 0 1246 26 1 0 20 0 2 0 29854772 304361472 41623 18446744073709551615 140492387160064 140492391467416 140735104004608 140735103996368 140492355905099 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26523/statm: 74307 41623 10360 1052 0 49644 0
[pid=26523/tid=26528] ppid=26522 vsize=297228 CPUtime=9.33
/proc/26523/task/26528/stat : 26528 (aptitude) R 26522 26523 17863 34816 17863 4202560 24620 2209 0 0 921 11 1 0 20 0 2 0 29854849 304361472 41623 18446744073709551615 140492387160064 140492391467416 140735104004608 140492274831032 140492389757113 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.73
Current children cumulated vsize (KiB) 297228

[startup+19.2003 s]
/proc/loadavg: 1.05 1.11 1.08 2/57 26529
/proc/meminfo: memFree=608256/1022884 swapFree=0/0
[pid=26523] ppid=26522 vsize=337744 CPUtime=19.1
/proc/26523/stat : 26523 (aptitude) S 26522 26523 17863 34816 17863 4202496 56760 2209 0 0 1880 29 1 0 20 0 2 0 29854772 345849856 51753 18446744073709551615 140492387160064 140492391467416 140735104004608 140735103996368 140492355905099 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26523/statm: 84436 51753 10360 1052 0 59773 0
[pid=26523/tid=26528] ppid=26522 vsize=337744 CPUtime=15.69
/proc/26523/task/26528/stat : 26528 (aptitude) R 26522 26523 17863 34816 17863 4202560 34774 2209 0 0 1554 14 1 0 20 0 2 0 29854849 345849856 51753 18446744073709551615 140492387160064 140492391467416 140735104004608 140492274828824 140492389950140 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 19.1
Current children cumulated vsize (KiB) 337744

[startup+22.4002 s]
/proc/loadavg: 1.05 1.11 1.08 2/57 26529
/proc/meminfo: memFree=591392/1022884 swapFree=0/0
[pid=26523] ppid=26522 vsize=353380 CPUtime=22.28
/proc/26523/stat : 26523 (aptitude) S 26522 26523 17863 34816 17863 4202496 60683 2209 0 0 2195 32 1 0 20 0 2 0 29854772 361861120 55652 18446744073709551615 140492387160064 140492391467416 140735104004608 140735103996368 140492355905099 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26523/statm: 88345 55652 10360 1052 0 63682 0
[pid=26523/tid=26528] ppid=26522 vsize=353380 CPUtime=18.88
/proc/26523/task/26528/stat : 26528 (aptitude) R 26522 26523 17863 34816 17863 4202560 38697 2209 0 0 1869 18 1 0 20 0 2 0 29854849 361861120 55652 18446744073709551615 140492387160064 140492391467416 140735104004608 140492274828824 140492382559793 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 22.28
Current children cumulated vsize (KiB) 353380

[startup+23.2032 s]
/proc/loadavg: 1.05 1.11 1.08 2/57 26529
/proc/meminfo: memFree=587920/1022884 swapFree=0/0
[pid=26523] ppid=26522 vsize=354892 CPUtime=23.08
/proc/26523/stat : 26523 (aptitude) R 26522 26523 17863 34816 17863 4202496 61306 2209 0 0 2274 33 1 0 20 0 2 0 29854772 363409408 56220 18446744073709551615 140492387160064 140492391467416 140735104004608 140735103994744 140492344651376 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26523/statm: 88723 56220 10408 1052 0 64053 0
[pid=26523/tid=26528] ppid=26522 vsize=354892 CPUtime=19.29
/proc/26523/task/26528/stat : 26528 (aptitude) S 26522 26523 17863 34816 17863 4202560 39090 2209 0 0 1910 18 1 0 20 0 2 0 29854849 363409408 56220 18446744073709551615 140492387160064 140492391467416 140735104004608 140492274837504 140492355904212 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 23.08
Current children cumulated vsize (KiB) 354892

[startup+23.6018 s]
/proc/loadavg: 1.05 1.11 1.08 2/57 26529
/proc/meminfo: memFree=587920/1022884 swapFree=0/0
[pid=26523] ppid=26522 vsize=354892 CPUtime=23.47
/proc/26523/stat : 26523 (aptitude) R 26522 26523 17863 34816 17863 4202496 63943 2209 0 0 2309 37 1 0 20 0 2 0 29854772 363409408 56269 18446744073709551615 140492387160064 140492391467416 140735104004608 140735103994368 140492344863030 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26523/statm: 88723 56269 10409 1052 0 64053 0
[pid=26523/tid=26528] ppid=26522 vsize=354892 CPUtime=19.29
/proc/26523/task/26528/stat : 26528 (aptitude) S 26522 26523 17863 34816 17863 4202560 39090 2209 0 0 1910 18 1 0 20 0 2 0 29854849 363409408 56269 18446744073709551615 140492387160064 140492391467416 140735104004608 140492274837504 140492355904212 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 23.47
Current children cumulated vsize (KiB) 354892

[startup+23.8003 s]
/proc/loadavg: 1.05 1.11 1.08 2/57 26529
/proc/meminfo: memFree=587920/1022884 swapFree=0/0
[pid=26523] ppid=26522 vsize=183824 CPUtime=23.66
/proc/26523/stat : 26523 (aptitude) R 26522 26523 17863 34816 17863 4202496 64658 2707 0 0 2318 47 1 0 20 0 1 0 29854772 188235776 13689 18446744073709551615 140492387160064 140492391467416 140735104004608 140735104001640 140492345041175 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26523/statm: 45956 13689 1503 1052 0 30212 0
Current children cumulated CPU time (s) 23.66
Current children cumulated vsize (KiB) 183824

Child status: 0
Real time (s): 23.8133
CPU time (s): 23.7015
CPU user time (s): 23.2054
CPU system time (s): 0.496031
CPU usage (%): 99.5305
Max. virtual memory (cumulated for all children) (KiB): 354892

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 23.2054
system time used= 0.496031
maximum resident set size= 225664
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 67460
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= 103
involuntary context switches= 454

runsolver used 0.032002 second user time and 0.080005 second system time

The end