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/48.runsolver.aptitude aptitude -s -y --without-recommends install mozilla user-es libgstreamer-plugins0.8-dev gnustep-netclasses admesh 

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.05 1.08 1.05 2/55 25634
/proc/meminfo: memFree=834552/1022884 swapFree=0/0
[pid=25634] ppid=25633 vsize=3152 CPUtime=0
/proc/25634/stat : 25634 (runsolver) R 25633 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29537514 3227648 33 18446744073709551615 134512640 134586868 4286721792 4286719840 4151952432 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/25634/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.16498 s]
/proc/loadavg: 1.05 1.08 1.05 2/55 25634
/proc/meminfo: memFree=834552/1022884 swapFree=0/0
[pid=25634] ppid=25633 vsize=103288 CPUtime=0.15
/proc/25634/stat : 25634 (aptitude) R 25633 25634 17863 34816 17863 4202496 11289 1709 0 0 14 1 0 0 20 0 1 0 29537514 105766912 11091 18446744073709551615 140533615828992 140533620136344 140737004198528 140737004189792 140533610669544 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25634/statm: 25822 11091 9879 1052 0 1159 0
Current children cumulated CPU time (s) 0.15
Current children cumulated vsize (KiB) 103288

[startup+0.20029 s]
/proc/loadavg: 1.05 1.08 1.05 2/55 25634
/proc/meminfo: memFree=834552/1022884 swapFree=0/0
[pid=25634] ppid=25633 vsize=103288 CPUtime=0.19
/proc/25634/stat : 25634 (aptitude) R 25633 25634 17863 34816 17863 4202496 11299 1709 0 0 18 1 0 0 20 0 1 0 29537514 105766912 11101 18446744073709551615 140533615828992 140533620136344 140737004198528 140737004189792 140533616658017 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25634/statm: 25822 11101 9889 1052 0 1159 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 103288

[startup+0.300289 s]
/proc/loadavg: 1.05 1.08 1.05 2/55 25634
/proc/meminfo: memFree=834552/1022884 swapFree=0/0
[pid=25634] ppid=25633 vsize=103432 CPUtime=0.28
/proc/25634/stat : 25634 (aptitude) R 25633 25634 17863 34816 17863 4202496 11426 1709 0 0 27 1 0 0 20 0 1 0 29537514 105914368 11220 18446744073709551615 140533615828992 140533620136344 140737004198528 140737004188304 140533610682338 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25634/statm: 25858 11220 9956 1052 0 1195 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 103432

[startup+0.700212 s]
/proc/loadavg: 1.05 1.08 1.05 2/55 25634
/proc/meminfo: memFree=834552/1022884 swapFree=0/0
[pid=25634] ppid=25633 vsize=123068 CPUtime=0.68
/proc/25634/stat : 25634 (aptitude) R 25633 25634 17863 34816 17863 4202496 17687 1709 0 0 64 4 0 0 20 0 1 0 29537514 126021632 15965 18446744073709551615 140533615828992 140533620136344 140737004198528 140737004187960 140533573369367 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25634/statm: 30767 15965 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123068

[startup+1.50026 s]
/proc/loadavg: 1.04 1.08 1.05 2/57 25639
/proc/meminfo: memFree=814580/1022884 swapFree=0/0
[pid=25634] ppid=25633 vsize=136056 CPUtime=1.48
/proc/25634/stat : 25634 (aptitude) R 25633 25634 17863 34816 17863 4202496 20641 1709 0 0 140 8 0 0 20 0 2 0 29537514 139321344 17560 18446744073709551615 140533615828992 140533620136344 140737004198528 140737004189800 140533582143449 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25634/statm: 34014 17560 10207 1052 0 9351 0
[pid=25634/tid=25639] ppid=25633 vsize=136056 CPUtime=0
/proc/25634/task/25639/stat : 25639 (aptitude) S 25633 25634 17863 34816 17863 4202560 4 1709 0 0 0 0 0 0 20 0 2 0 29537591 139321344 17560 18446744073709551615 140533615828992 140533620136344 140737004198528 140533503506432 140533584573140 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 136056

[startup+3.10026 s]
/proc/loadavg: 1.04 1.08 1.05 2/57 25639
/proc/meminfo: memFree=804288/1022884 swapFree=0/0
[pid=25634] ppid=25633 vsize=137812 CPUtime=3.07
/proc/25634/stat : 25634 (aptitude) R 25633 25634 17863 34816 17863 4202496 21995 2208 0 0 293 14 0 0 20 0 2 0 29537514 141119488 17937 18446744073709551615 140533615828992 140533620136344 140737004198528 140737004185232 140533573339272 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25634/statm: 34453 17937 10303 1052 0 9790 0
[pid=25634/tid=25639] ppid=25633 vsize=137812 CPUtime=0
/proc/25634/task/25639/stat : 25639 (aptitude) S 25633 25634 17863 34816 17863 4202560 6 2208 0 0 0 0 0 0 20 0 2 0 29537591 141119488 17937 18446744073709551615 140533615828992 140533620136344 140737004198528 140533503506432 140533584573140 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 137812

[startup+6.30026 s]
/proc/loadavg: 1.04 1.08 1.05 2/57 25640
/proc/meminfo: memFree=767832/1022884 swapFree=0/0
[pid=25634] ppid=25633 vsize=250736 CPUtime=6.25
/proc/25634/stat : 25634 (aptitude) S 25633 25634 17863 34816 17863 4202496 34381 2208 0 0 609 16 0 0 20 0 2 0 29537514 256753664 30036 18446744073709551615 140533615828992 140533620136344 140737004198528 140737004190288 140533584574027 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25634/statm: 62684 30036 10359 1052 0 38021 0
[pid=25634/tid=25639] ppid=25633 vsize=250736 CPUtime=2.86
/proc/25634/task/25639/stat : 25639 (aptitude) R 25633 25634 17863 34816 17863 4202560 12385 2208 0 0 283 3 0 0 20 0 2 0 29537591 256753664 30036 18446744073709551615 140533615828992 140533620136344 140737004198528 140533503497752 140533617457490 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.25
Current children cumulated vsize (KiB) 250736

[startup+12.7003 s]
/proc/loadavg: 1.04 1.08 1.05 2/57 25640
/proc/meminfo: memFree=709676/1022884 swapFree=0/0
[pid=25634] ppid=25633 vsize=300248 CPUtime=12.62
/proc/25634/stat : 25634 (aptitude) S 25633 25634 17863 34816 17863 4202496 46989 2208 0 0 1243 19 0 0 20 0 2 0 29537514 307453952 42383 18446744073709551615 140533615828992 140533620136344 140737004198528 140737004190288 140533584574027 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25634/statm: 75062 42383 10359 1052 0 50399 0
[pid=25634/tid=25639] ppid=25633 vsize=300248 CPUtime=9.24
/proc/25634/task/25639/stat : 25639 (aptitude) R 25633 25634 17863 34816 17863 4202560 24993 2208 0 0 918 6 0 0 20 0 2 0 29537591 307453952 42383 18446744073709551615 140533615828992 140533620136344 140737004198528 140533503497752 140533573339463 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.62
Current children cumulated vsize (KiB) 300248

[startup+25.5003 s]
/proc/loadavg: 1.03 1.08 1.05 2/57 25640
/proc/meminfo: memFree=613204/1022884 swapFree=0/0
[pid=25634] ppid=25633 vsize=394148 CPUtime=25.36
/proc/25634/stat : 25634 (aptitude) S 25633 25634 17863 34816 17863 4202496 70884 2208 0 0 2506 30 0 0 20 0 2 0 29537514 403607552 65841 18446744073709551615 140533615828992 140533620136344 140737004198528 140737004190288 140533584574027 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25634/statm: 98537 65841 10360 1052 0 73874 0
[pid=25634/tid=25639] ppid=25633 vsize=394148 CPUtime=21.97
/proc/25634/task/25639/stat : 25639 (aptitude) R 25633 25634 17863 34816 17863 4202560 48888 2208 0 0 2181 16 0 0 20 0 2 0 29537591 403607552 65841 18446744073709551615 140533615828992 140533620136344 140737004198528 140533503497752 140533618505241 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.36
Current children cumulated vsize (KiB) 394148

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

[startup+25.6004 s]
/proc/loadavg: 1.03 1.08 1.05 2/57 25640
/proc/meminfo: memFree=613204/1022884 swapFree=0/0
[pid=25634] ppid=25633 vsize=394808 CPUtime=25.46
/proc/25634/stat : 25634 (aptitude) S 25633 25634 17863 34816 17863 4202496 71047 2208 0 0 2516 30 0 0 20 0 2 0 29537514 404283392 66004 18446744073709551615 140533615828992 140533620136344 140737004198528 140737004190288 140533584574027 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25634/statm: 98702 66004 10360 1052 0 74039 0
[pid=25634/tid=25639] ppid=25633 vsize=394808 CPUtime=22.07
/proc/25634/task/25639/stat : 25639 (aptitude) R 25633 25634 17863 34816 17863 4202560 49051 2208 0 0 2191 16 0 0 20 0 2 0 29537591 404283392 66004 18446744073709551615 140533615828992 140533620136344 140737004198528 140533503499960 140533618030363 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.46
Current children cumulated vsize (KiB) 394808

[startup+27.2003 s]
/proc/loadavg: 1.03 1.08 1.05 2/57 25640
/proc/meminfo: memFree=606012/1022884 swapFree=0/0
[pid=25634] ppid=25633 vsize=405968 CPUtime=27.05
/proc/25634/stat : 25634 (aptitude) S 25633 25634 17863 34816 17863 4202496 73833 2208 0 0 2675 30 0 0 20 0 2 0 29537514 415711232 68782 18446744073709551615 140533615828992 140533620136344 140737004198528 140737004190288 140533584574027 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25634/statm: 101492 68782 10360 1052 0 76829 0
[pid=25634/tid=25639] ppid=25633 vsize=405968 CPUtime=23.66
/proc/25634/task/25639/stat : 25639 (aptitude) R 25633 25634 17863 34816 17863 4202560 51837 2208 0 0 2350 16 0 0 20 0 2 0 29537591 415711232 68782 18446744073709551615 140533615828992 140533620136344 140737004198528 140533503497752 140533573329327 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 27.05
Current children cumulated vsize (KiB) 405968

[startup+28.0003 s]
/proc/loadavg: 1.03 1.08 1.05 2/57 25640
/proc/meminfo: memFree=598448/1022884 swapFree=0/0
[pid=25634] ppid=25633 vsize=411248 CPUtime=27.84
/proc/25634/stat : 25634 (aptitude) S 25633 25634 17863 34816 17863 4202496 75149 2208 0 0 2754 30 0 0 20 0 2 0 29537514 421117952 70098 18446744073709551615 140533615828992 140533620136344 140737004198528 140737004190288 140533584574027 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25634/statm: 102812 70098 10361 1052 0 78149 0
[pid=25634/tid=25639] ppid=25633 vsize=411248 CPUtime=24.46
/proc/25634/task/25639/stat : 25639 (aptitude) R 25633 25634 17863 34816 17863 4202560 53153 2208 0 0 2429 17 0 0 20 0 2 0 29537591 421117952 70098 18446744073709551615 140533615828992 140533620136344 140737004198528 140533503497752 140533618527786 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 27.84
Current children cumulated vsize (KiB) 411248

[startup+28.8002 s]
/proc/loadavg: 1.03 1.08 1.05 2/57 25640
/proc/meminfo: memFree=592620/1022884 swapFree=0/0
[pid=25634] ppid=25633 vsize=412768 CPUtime=28.64
/proc/25634/stat : 25634 (aptitude) R 25633 25634 17863 34816 17863 4202496 76339 2208 0 0 2834 30 0 0 20 0 2 0 29537514 422674432 70636 18446744073709551615 140533615828992 140533620136344 140737004198528 140737004188616 140533610665584 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25634/statm: 103192 70636 10410 1052 0 78522 0
[pid=25634/tid=25639] ppid=25633 vsize=412768 CPUtime=24.68
/proc/25634/task/25639/stat : 25639 (aptitude) S 25633 25634 17863 34816 17863 4202560 53513 2208 0 0 2451 17 0 0 20 0 2 0 29537591 422674432 70636 18446744073709551615 140533615828992 140533620136344 140737004198528 140533503506432 140533584573140 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 28.64
Current children cumulated vsize (KiB) 412768

[startup+29.2003 s]
/proc/loadavg: 1.03 1.08 1.05 2/57 25640
/proc/meminfo: memFree=592620/1022884 swapFree=0/0
[pid=25634] ppid=25633 vsize=412768 CPUtime=29.04
/proc/25634/stat : 25634 (aptitude) R 25633 25634 17863 34816 17863 4202496 78564 2709 0 0 2866 37 0 1 20 0 2 0 29537514 422674432 70736 18446744073709551615 140533615828992 140533620136344 140737004198528 140737004189240 140533582138984 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25634/statm: 103192 70736 10410 1052 0 78522 0
[pid=25634/tid=25639] ppid=25633 vsize=412768 CPUtime=24.69
/proc/25634/task/25639/stat : 25639 (aptitude) S 25633 25634 17863 34816 17863 4202560 53513 2709 0 0 2451 17 0 1 20 0 2 0 29537591 422674432 70736 18446744073709551615 140533615828992 140533620136344 140737004198528 140533503506432 140533584573140 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 29.04
Current children cumulated vsize (KiB) 412768

[startup+29.3002 s]
/proc/loadavg: 1.03 1.08 1.05 2/57 25640
/proc/meminfo: memFree=592620/1022884 swapFree=0/0
[pid=25634] ppid=25633 vsize=412768 CPUtime=29.13
/proc/25634/stat : 25634 (aptitude) R 25633 25634 17863 34816 17863 4202496 78721 2709 0 0 2872 40 0 1 20 0 2 0 29537514 422674432 70560 18446744073709551615 140533615828992 140533620136344 140737004198528 140737004190344 140533573673029 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25634/statm: 103192 70560 10410 1052 0 78522 0
[pid=25634/tid=25639] ppid=25633 vsize=412768 CPUtime=24.69
/proc/25634/task/25639/stat : 25639 (aptitude) S 25633 25634 17863 34816 17863 4202560 53513 2709 0 0 2451 17 0 1 20 0 2 0 29537591 422674432 70560 18446744073709551615 140533615828992 140533620136344 140737004198528 140533503506432 140533584573140 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 29.13
Current children cumulated vsize (KiB) 412768

Child status: 0
Real time (s): 29.3901
CPU time (s): 29.2458
CPU user time (s): 28.7538
CPU system time (s): 0.49203
CPU usage (%): 99.509
Max. virtual memory (cumulated for all children) (KiB): 412768

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 28.7538
system time used= 0.49203
maximum resident set size= 283372
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 81949
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= 114
involuntary context switches= 553

runsolver used 0.016001 second user time and 0.124007 second system time

The end