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/19.runsolver.aptitude aptitude -s -y --without-recommends install gnome-gpg hostap-modules-2.6.8-4-386 rarpd shntool lesstif2 

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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 1.08 1.07 0.84 2/55 20984
/proc/meminfo: memFree=913228/1022884 swapFree=0/0
[pid=20984] ppid=20983 vsize=3152 CPUtime=0
/proc/20984/stat : 20984 (runsolver) R 20983 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28335320 3227648 33 18446744073709551615 134512640 134586868 4293495088 4293493136 4151387184 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/20984/statm: 788 33 0 19 0 73 0

[startup+0.190407 s]
/proc/loadavg: 1.08 1.07 0.84 2/55 20984
/proc/meminfo: memFree=913228/1022884 swapFree=0/0
[pid=20984] ppid=20983 vsize=89152 CPUtime=0.17
/proc/20984/stat : 20984 (aptitude) R 20983 20984 17863 34816 17863 4202496 7775 1708 0 0 16 1 0 0 20 0 1 0 28335320 91291648 7575 18446744073709551615 140533870346240 140533874653592 140733785679312 140733785670576 140533865187158 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/20984/statm: 22288 7575 6665 1052 0 858 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 89152

[startup+0.200403 s]
/proc/loadavg: 1.08 1.07 0.84 2/55 20984
/proc/meminfo: memFree=913228/1022884 swapFree=0/0
[pid=20984] ppid=20983 vsize=89152 CPUtime=0.18
/proc/20984/stat : 20984 (aptitude) D 20983 20984 17863 34816 17863 4202496 7780 1708 0 0 17 1 0 0 20 0 1 0 28335320 91291648 7579 18446744073709551615 140533870346240 140533874653592 140733785679312 140733785670488 140533828192080 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/20984/statm: 22288 7579 6669 1052 0 858 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 89152

[startup+0.308071 s]
/proc/loadavg: 1.08 1.07 0.84 2/55 20984
/proc/meminfo: memFree=913228/1022884 swapFree=0/0
[pid=20984] ppid=20983 vsize=100164 CPUtime=0.28
/proc/20984/stat : 20984 (aptitude) R 20983 20984 17863 34816 17863 4202496 11279 1708 0 0 26 2 0 0 20 0 1 0 28335320 102567936 10326 18446744073709551615 140533870346240 140533874653592 140733785679312 140733785668824 140533873284955 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/20984/statm: 25041 10326 6742 1052 0 3611 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 100164

[startup+0.700199 s]
/proc/loadavg: 1.08 1.07 0.84 2/55 20984
/proc/meminfo: memFree=913228/1022884 swapFree=0/0
[pid=20984] ppid=20983 vsize=108136 CPUtime=0.67
/proc/20984/stat : 20984 (aptitude) R 20983 20984 17863 34816 17863 4202496 12159 1708 0 0 63 4 0 0 20 0 2 0 28335320 110731264 10534 18446744073709551615 140533870346240 140533874653592 140733785679312 140733785672936 140533865200876 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/20984/statm: 27034 10534 6925 1052 0 5604 0
Current children cumulated CPU time (s) 0.67
Current children cumulated vsize (KiB) 108136

[startup+1.50023 s]
/proc/loadavg: 1.08 1.07 0.84 2/57 20989
/proc/meminfo: memFree=892388/1022884 swapFree=0/0
[pid=20984] ppid=20983 vsize=115468 CPUtime=1.47
/proc/20984/stat : 20984 (aptitude) R 20983 20984 17863 34816 17863 4202496 14425 2207 0 0 139 8 0 0 20 0 2 0 28335320 118239232 12359 18446744073709551615 140533870346240 140533874653592 140733785679312 140733785671336 140533827856761 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/20984/statm: 28867 12359 7073 1052 0 7437 0
[pid=20984/tid=20989] ppid=20983 vsize=115468 CPUtime=0
/proc/20984/task/20989/stat : 20989 (aptitude) S 20983 20984 17863 34816 17863 4202560 6 2207 0 0 0 0 0 0 20 0 2 0 28335366 118239232 12359 18446744073709551615 140533870346240 140533874653592 140733785679312 140533773752320 140533839090388 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) 115468

[startup+3.10024 s]
/proc/loadavg: 1.08 1.07 0.84 2/57 20990
/proc/meminfo: memFree=885692/1022884 swapFree=0/0
[pid=20984] ppid=20983 vsize=136468 CPUtime=3.06
/proc/20984/stat : 20984 (aptitude) S 20983 20984 17863 34816 17863 4202496 20806 2207 0 0 294 12 0 0 20 0 2 0 28335320 139743232 17829 18446744073709551615 140533870346240 140533874653592 140733785679312 140733785671072 140533839091275 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/20984/statm: 34117 17829 7129 1052 0 12687 0
[pid=20984/tid=20989] ppid=20983 vsize=136468 CPUtime=1.02
/proc/20984/task/20989/stat : 20989 (aptitude) R 20983 20984 17863 34816 17863 4202560 6158 2207 0 0 98 4 0 0 20 0 2 0 28335366 139743232 17829 18446744073709551615 140533870346240 140533874653592 140733785679312 140533773745848 140533873053926 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.06
Current children cumulated vsize (KiB) 136468

[startup+6.30024 s]
/proc/loadavg: 1.07 1.07 0.85 2/57 20990
/proc/meminfo: memFree=836588/1022884 swapFree=0/0
[pid=20984] ppid=20983 vsize=180564 CPUtime=6.24
/proc/20984/stat : 20984 (aptitude) S 20983 20984 17863 34816 17863 4202496 31819 2207 0 0 608 16 0 0 20 0 2 0 28335320 184897536 28836 18446744073709551615 140533870346240 140533874653592 140733785679312 140733785671072 140533839091275 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/20984/statm: 45141 28836 7129 1052 0 23711 0
[pid=20984/tid=20989] ppid=20983 vsize=180564 CPUtime=4.21
/proc/20984/task/20989/stat : 20989 (aptitude) R 20983 20984 17863 34816 17863 4202560 17171 2207 0 0 412 9 0 0 20 0 2 0 28335366 184897536 28836 18446744073709551615 140533870346240 140533874653592 140733785679312 140533773743992 140533872859576 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.24
Current children cumulated vsize (KiB) 180564

[startup+12.7002 s]
/proc/loadavg: 1.07 1.07 0.85 2/57 20990
/proc/meminfo: memFree=778060/1022884 swapFree=0/0
[pid=20984] ppid=20983 vsize=297276 CPUtime=12.61
/proc/20984/stat : 20984 (aptitude) S 20983 20984 17863 34816 17863 4202496 44642 2207 0 0 1239 22 0 0 20 0 2 0 28335320 304410624 41633 18446744073709551615 140533870346240 140533874653592 140733785679312 140733785671072 140533839091275 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/20984/statm: 74319 41633 7129 1052 0 52889 0
[pid=20984/tid=20989] ppid=20983 vsize=297276 CPUtime=10.58
/proc/20984/task/20989/stat : 20989 (aptitude) R 20983 20984 17863 34816 17863 4202560 29993 2207 0 0 1043 15 0 0 20 0 2 0 28335366 304410624 41633 18446744073709551615 140533870346240 140533874653592 140733785679312 140533773743640 140533873044830 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) 297276

[startup+25.5003 s]
/proc/loadavg: 1.05 1.06 0.85 2/57 20990
/proc/meminfo: memFree=707504/1022884 swapFree=0/0
[pid=20984] ppid=20983 vsize=365600 CPUtime=25.34
/proc/20984/stat : 20984 (aptitude) S 20983 20984 17863 34816 17863 4202496 61889 2207 0 0 2500 34 0 0 20 0 2 0 28335320 374374400 58691 18446744073709551615 140533870346240 140533874653592 140733785679312 140733785671072 140533839091275 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/20984/statm: 91400 58691 7129 1052 0 69970 0
[pid=20984/tid=20989] ppid=20983 vsize=365600 CPUtime=23.32
/proc/20984/task/20989/stat : 20989 (aptitude) R 20983 20984 17863 34816 17863 4202560 47240 2207 0 0 2305 27 0 0 20 0 2 0 28335366 374374400 58691 18446744073709551615 140533870346240 140533874653592 140733785679312 140533773745848 140533873054305 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.34
Current children cumulated vsize (KiB) 365600

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

[startup+25.6003 s]
/proc/loadavg: 1.05 1.06 0.85 2/57 20990
/proc/meminfo: memFree=707504/1022884 swapFree=0/0
[pid=20984] ppid=20983 vsize=366128 CPUtime=25.44
/proc/20984/stat : 20984 (aptitude) S 20983 20984 17863 34816 17863 4202496 62020 2207 0 0 2510 34 0 0 20 0 2 0 28335320 374915072 58822 18446744073709551615 140533870346240 140533874653592 140733785679312 140733785671072 140533839091275 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/20984/statm: 91532 58822 7129 1052 0 70102 0
[pid=20984/tid=20989] ppid=20983 vsize=366128 CPUtime=23.42
/proc/20984/task/20989/stat : 20989 (aptitude) R 20983 20984 17863 34816 17863 4202560 47371 2207 0 0 2315 27 0 0 20 0 2 0 28335366 374915072 58822 18446744073709551615 140533870346240 140533874653592 140733785679312 140533773743592 140533872992538 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.44
Current children cumulated vsize (KiB) 366128

[startup+38.4002 s]
/proc/loadavg: 1.04 1.06 0.85 2/57 20990
/proc/meminfo: memFree=653440/1022884 swapFree=0/0
[pid=20984] ppid=20983 vsize=422324 CPUtime=38.19
/proc/20984/stat : 20984 (aptitude) S 20983 20984 17863 34816 17863 4202496 76142 2207 0 0 3774 45 0 0 20 0 2 0 28335320 432459776 72905 18446744073709551615 140533870346240 140533874653592 140733785679312 140733785671072 140533839091275 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/20984/statm: 105581 72905 7143 1052 0 84151 0
[pid=20984/tid=20989] ppid=20983 vsize=422324 CPUtime=36.16
/proc/20984/task/20989/stat : 20989 (aptitude) R 20983 20984 17863 34816 17863 4202560 61486 2207 0 0 3578 38 0 0 20 0 2 0 28335366 432459776 72905 18446744073709551615 140533870346240 140533874653592 140733785679312 140533773745800 140533870991666 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 38.19
Current children cumulated vsize (KiB) 422324

[startup+41.6002 s]
/proc/loadavg: 1.04 1.06 0.85 2/57 20990
/proc/meminfo: memFree=640048/1022884 swapFree=0/0
[pid=20984] ppid=20983 vsize=435204 CPUtime=41.38
/proc/20984/stat : 20984 (aptitude) S 20983 20984 17863 34816 17863 4202496 79371 2207 0 0 4092 46 0 0 20 0 2 0 28335320 445648896 76134 18446744073709551615 140533870346240 140533874653592 140733785679312 140733785671072 140533839091275 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/20984/statm: 108801 76134 7143 1052 0 87371 0
[pid=20984/tid=20989] ppid=20983 vsize=435204 CPUtime=39.34
/proc/20984/task/20989/stat : 20989 (aptitude) R 20983 20984 17863 34816 17863 4202560 64715 2207 0 0 3896 38 0 0 20 0 2 0 28335366 445648896 76134 18446744073709551615 140533870346240 140533874653592 140733785679312 140533773743592 140533872557149 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 41.38
Current children cumulated vsize (KiB) 435204

[startup+44.8002 s]
/proc/loadavg: 1.04 1.06 0.85 2/57 20990
/proc/meminfo: memFree=625664/1022884 swapFree=0/0
[pid=20984] ppid=20983 vsize=449660 CPUtime=44.56
/proc/20984/stat : 20984 (aptitude) S 20983 20984 17863 34816 17863 4202496 83003 2207 0 0 4409 47 0 0 20 0 2 0 28335320 460451840 79757 18446744073709551615 140533870346240 140533874653592 140733785679312 140733785671072 140533839091275 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/20984/statm: 112415 79757 7143 1052 0 90985 0
[pid=20984/tid=20989] ppid=20983 vsize=449660 CPUtime=42.52
/proc/20984/task/20989/stat : 20989 (aptitude) R 20983 20984 17863 34816 17863 4202560 68347 2207 0 0 4213 39 0 0 20 0 2 0 28335366 460451840 79757 18446744073709551615 140533870346240 140533874653592 140733785679312 140533773743592 140533872974736 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 44.56
Current children cumulated vsize (KiB) 449660

[startup+46.4003 s]
/proc/loadavg: 1.04 1.06 0.85 2/57 20990
/proc/meminfo: memFree=615248/1022884 swapFree=0/0
[pid=20984] ppid=20983 vsize=455188 CPUtime=46.15
/proc/20984/stat : 20984 (aptitude) R 20983 20984 17863 34816 17863 4202496 84711 2207 0 0 4567 48 0 0 20 0 2 0 28335320 466112512 81341 18446744073709551615 140533870346240 140533874653592 140733785679312 140733785669448 140533827837522 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/20984/statm: 113797 81341 7191 1052 0 92360 0
[pid=20984/tid=20989] ppid=20983 vsize=455188 CPUtime=43.58
/proc/20984/task/20989/stat : 20989 (aptitude) S 20983 20984 17863 34816 17863 4202560 69688 2207 0 0 4318 40 0 0 20 0 2 0 28335366 466112512 81341 18446744073709551615 140533870346240 140533874653592 140733785679312 140533773752320 140533839090388 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 46.15
Current children cumulated vsize (KiB) 455188

[startup+46.8002 s]
/proc/loadavg: 1.04 1.06 0.85 2/57 20990
/proc/meminfo: memFree=615248/1022884 swapFree=0/0
[pid=20984] ppid=20983 vsize=455188 CPUtime=46.55
/proc/20984/stat : 20984 (aptitude) R 20983 20984 17863 34816 17863 4202496 86631 2207 0 0 4607 48 0 0 20 0 2 0 28335320 466112512 81268 18446744073709551615 140533870346240 140533874653592 140733785679312 140733785671512 140533872553732 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/20984/statm: 113797 81268 7192 1052 0 92360 0
[pid=20984/tid=20989] ppid=20983 vsize=455188 CPUtime=43.58
/proc/20984/task/20989/stat : 20989 (aptitude) S 20983 20984 17863 34816 17863 4202560 69688 2207 0 0 4318 40 0 0 20 0 2 0 28335366 466112512 81268 18446744073709551615 140533870346240 140533874653592 140733785679312 140533773752320 140533839090388 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 46.55
Current children cumulated vsize (KiB) 455188

[startup+47.0011 s]
/proc/loadavg: 1.04 1.06 0.85 2/57 20990
/proc/meminfo: memFree=615248/1022884 swapFree=0/0
[pid=20984] ppid=20983 vsize=455188 CPUtime=46.76
/proc/20984/stat : 20984 (aptitude) R 20983 20984 17863 34816 17863 4202496 87387 2706 0 0 4615 59 1 1 20 0 2 0 28335320 466112512 48500 18446744073709551615 140533870346240 140533874653592 140733785679312 140733785675576 140533828212202 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/20984/statm: 113797 48500 7192 1052 0 92360 0
[pid=20984/tid=20989] ppid=20983 vsize=455188 CPUtime=43.6
/proc/20984/task/20989/stat : 20989 (aptitude) S 20983 20984 17863 34816 17863 4202560 69688 2706 0 0 4318 40 1 1 20 0 2 0 28335366 466112512 48500 18446744073709551615 140533870346240 140533874653592 140733785679312 140533773752320 140533839090388 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 46.76
Current children cumulated vsize (KiB) 455188

Child status: 0
Real time (s): 47.0491
CPU time (s): 46.8229
CPU user time (s): 46.1669
CPU system time (s): 0.656041
CPU usage (%): 99.5192
Max. virtual memory (cumulated for all children) (KiB): 455188

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 46.1669
system time used= 0.656041
maximum resident set size= 325708
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 90241
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= 156
involuntary context switches= 862

runsolver used 0.096006 second user time and 0.128008 second system time

The end