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/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.34 1.12 1.03 2/55 22965
/proc/meminfo: memFree=911864/1022884 swapFree=0/0
[pid=22965] ppid=22964 vsize=3152 CPUtime=0
/proc/22965/stat : 22965 (runsolver) R 22964 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28760538 3227648 32 18446744073709551615 134512640 134586868 4290369936 4290367984 4151497776 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/22965/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.15982 s]
/proc/loadavg: 1.34 1.12 1.03 2/55 22965
/proc/meminfo: memFree=911864/1022884 swapFree=0/0
[pid=22965] ppid=22964 vsize=12328 CPUtime=0
/proc/22965/stat : 22965 (aptitude) D 22964 22965 17863 34816 17863 4202496 131 0 7 0 0 0 0 0 20 0 1 0 28760538 12623872 54 18446744073709551615 139727165947904 139727170255256 140734872600960 140734872598408 139727163802071 0 0 0 0 0 0 0 17 0 0 0 15 0 0
/proc/22965/statm: 3082 54 38 1052 0 30 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 12328

[startup+0.20035 s]
/proc/loadavg: 1.34 1.12 1.03 2/55 22965
/proc/meminfo: memFree=911864/1022884 swapFree=0/0
[pid=22965] ppid=22964 vsize=19848 CPUtime=0
/proc/22965/stat : 22965 (aptitude) D 22964 22965 17863 34816 17863 4202496 142 0 11 0 0 0 0 0 20 0 1 0 28760538 20324352 67 18446744073709551615 139727165947904 139727170255256 140734872600960 140734872598264 139727163802167 0 0 0 0 0 0 0 17 0 0 0 19 0 0
/proc/22965/statm: 4962 67 45 1052 0 31 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 19848

[startup+0.300343 s]
/proc/loadavg: 1.34 1.12 1.03 2/55 22965
/proc/meminfo: memFree=911864/1022884 swapFree=0/0
[pid=22965] ppid=22964 vsize=28716 CPUtime=0
/proc/22965/stat : 22965 (aptitude) D 22964 22965 17863 34816 17863 4202496 154 0 16 0 0 0 0 0 20 0 1 0 28760538 29405184 81 18446744073709551615 139727165947904 139727170255256 140734872600960 140734872598120 139727163802167 0 0 0 0 0 0 0 17 0 0 0 28 0 0
/proc/22965/statm: 7179 81 52 1052 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 28716

[startup+0.700293 s]
/proc/loadavg: 1.34 1.12 1.03 2/55 22965
/proc/meminfo: memFree=911864/1022884 swapFree=0/0
[pid=22965] ppid=22964 vsize=54968 CPUtime=0
/proc/22965/stat : 22965 (aptitude) D 22964 22965 17863 34816 17863 4202496 900 0 54 0 0 0 0 0 20 0 1 0 28760538 56287232 846 18446744073709551615 139727165947904 139727170255256 140734872600960 140734872600672 139727166747248 0 0 0 0 0 0 0 17 0 0 0 67 0 0
/proc/22965/statm: 13742 846 703 1052 0 106 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 54968

[startup+1.50026 s]
/proc/loadavg: 1.34 1.12 1.03 1/56 22966
/proc/meminfo: memFree=903540/1022884 swapFree=0/0
[pid=22965] ppid=22964 vsize=100508 CPUtime=0.02
/proc/22965/stat : 22965 (aptitude) D 22964 22965 17863 34816 17863 4202496 2759 1705 107 4 1 1 0 0 20 0 1 0 28760538 102920192 2667 18446744073709551615 139727165947904 139727170255256 140734872600960 140734872592432 139727160997786 0 134217728 4096 0 0 0 0 17 0 0 0 139 0 0
/proc/22965/statm: 25127 2667 1493 1052 0 1122 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 100508

[startup+3.10036 s]
/proc/loadavg: 1.34 1.12 1.03 2/56 22969
/proc/meminfo: memFree=896720/1022884 swapFree=0/0
[pid=22965] ppid=22964 vsize=119772 CPUtime=0.46
/proc/22965/stat : 22965 (aptitude) R 22964 22965 17863 34816 17863 4202496 16208 1705 281 4 42 4 0 0 20 0 1 0 28760538 122646528 14767 18446744073709551615 139727165947904 139727170255256 140734872600960 140734872590392 139727134703984 0 134217728 4096 0 0 0 0 17 0 0 0 254 0 0
/proc/22965/statm: 29943 14767 9317 1052 0 5938 0
Current children cumulated CPU time (s) 0.46
Current children cumulated vsize (KiB) 119772
heavy processes:

[startup+6.30024 s]
/proc/loadavg: 1.31 1.12 1.03 2/57 22971
/proc/meminfo: memFree=781384/1022884 swapFree=0/0
[pid=22965] ppid=22964 vsize=133888 CPUtime=3.02
/proc/22965/stat : 22965 (aptitude) R 22964 22965 17863 34816 17863 4202496 20317 2201 290 5 286 16 0 0 20 0 2 0 28760538 137101312 16942 18446744073709551615 139727165947904 139727170255256 140734872600960 140734872587664 139727123448080 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 317 0 0
/proc/22965/statm: 33472 16942 9644 1052 0 9467 0
[pid=22965/tid=22970] ppid=22964 vsize=133888 CPUtime=0
/proc/22965/task/22970/stat : 22970 (aptitude) S 22964 22965 17863 34816 17863 4202560 6 2201 0 5 0 0 0 0 20 0 2 0 28760917 137101312 16942 18446744073709551615 139727165947904 139727170255256 140734872600960 139727056775168 139727134692052 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.02
Current children cumulated vsize (KiB) 133888
heavy processes:

[startup+12.7003 s]
/proc/loadavg: 1.29 1.12 1.03 2/57 22971
/proc/meminfo: memFree=712324/1022884 swapFree=0/0
[pid=22965] ppid=22964 vsize=270060 CPUtime=9.39
/proc/22965/stat : 22965 (aptitude) S 22964 22965 17863 34816 17863 4202496 38982 2201 290 5 916 23 0 0 20 0 2 0 28760538 276541440 34834 18446744073709551615 139727165947904 139727170255256 140734872600960 140734872592720 139727134692939 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 317 0 0
/proc/22965/statm: 67515 34834 9700 1052 0 43510 0
[pid=22965/tid=22970] ppid=22964 vsize=270060 CPUtime=6.24
/proc/22965/task/22970/stat : 22970 (aptitude) R 22964 22965 17863 34816 17863 4202560 18664 2201 0 5 617 7 0 0 20 0 2 0 28760917 276541440 34834 18446744073709551615 139727165947904 139727170255256 140734872600960 139727056766488 139727167576225 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 9.39
Current children cumulated vsize (KiB) 270060
heavy processes:

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

[startup+12.8034 s]
/proc/loadavg: 1.29 1.12 1.03 2/57 22971
/proc/meminfo: memFree=709720/1022884 swapFree=0/0
[pid=22965] ppid=22964 vsize=270324 CPUtime=9.49
/proc/22965/stat : 22965 (aptitude) S 22964 22965 17863 34816 17863 4202496 39060 2201 290 5 926 23 0 0 20 0 2 0 28760538 276811776 34912 18446744073709551615 139727165947904 139727170255256 140734872600960 140734872592720 139727134692939 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 317 0 0
/proc/22965/statm: 67581 34912 9700 1052 0 43576 0
[pid=22965/tid=22970] ppid=22964 vsize=270324 CPUtime=6.34
/proc/22965/task/22970/stat : 22970 (aptitude) R 22964 22965 17863 34816 17863 4202560 18742 2201 0 5 627 7 0 0 20 0 2 0 28760917 276811776 34912 18446744073709551615 139727165947904 139727170255256 140734872600960 139727056766488 139727123458144 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 9.49
Current children cumulated vsize (KiB) 270324

[startup+16.0002 s]
/proc/loadavg: 1.27 1.11 1.03 2/57 22971
/proc/meminfo: memFree=697568/1022884 swapFree=0/0
[pid=22965] ppid=22964 vsize=284712 CPUtime=12.67
/proc/22965/stat : 22965 (aptitude) S 22964 22965 17863 34816 17863 4202496 42743 2201 290 5 1242 25 0 0 20 0 2 0 28760538 291545088 38519 18446744073709551615 139727165947904 139727170255256 140734872600960 140734872592720 139727134692939 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 317 0 0
/proc/22965/statm: 71178 38519 9700 1052 0 47173 0
[pid=22965/tid=22970] ppid=22964 vsize=284712 CPUtime=9.52
/proc/22965/task/22970/stat : 22970 (aptitude) R 22964 22965 17863 34816 17863 4202560 22425 2201 0 5 943 9 0 0 20 0 2 0 28760917 291545088 38519 18446744073709551615 139727165947904 139727170255256 140734872600960 139727056766488 139727168519035 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.67
Current children cumulated vsize (KiB) 284712

[startup+19.2002 s]
/proc/loadavg: 1.27 1.11 1.03 2/57 22971
/proc/meminfo: memFree=676860/1022884 swapFree=0/0
[pid=22965] ppid=22964 vsize=307376 CPUtime=15.86
/proc/22965/stat : 22965 (aptitude) S 22964 22965 17863 34816 17863 4202496 48419 2201 290 5 1558 28 0 0 20 0 2 0 28760538 314753024 44144 18446744073709551615 139727165947904 139727170255256 140734872600960 140734872592720 139727134692939 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 317 0 0
/proc/22965/statm: 76844 44144 9700 1052 0 52839 0
[pid=22965/tid=22970] ppid=22964 vsize=307376 CPUtime=12.7
/proc/22965/task/22970/stat : 22970 (aptitude) R 22964 22965 17863 34816 17863 4202560 28101 2201 0 5 1259 11 0 0 20 0 2 0 28760917 314753024 44144 18446744073709551615 139727165947904 139727170255256 140734872600960 139727056766488 139727123458354 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 15.86
Current children cumulated vsize (KiB) 307376

[startup+20.8002 s]
/proc/loadavg: 1.24 1.11 1.03 2/57 22971
/proc/meminfo: memFree=667312/1022884 swapFree=0/0
[pid=22965] ppid=22964 vsize=320048 CPUtime=17.45
/proc/22965/stat : 22965 (aptitude) S 22964 22965 17863 34816 17863 4202496 51639 2201 290 5 1716 29 0 0 20 0 2 0 28760538 327729152 47343 18446744073709551615 139727165947904 139727170255256 140734872600960 140734872592720 139727134692939 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 317 0 0
/proc/22965/statm: 80012 47343 9700 1052 0 56007 0
[pid=22965/tid=22970] ppid=22964 vsize=320048 CPUtime=14.3
/proc/22965/task/22970/stat : 22970 (aptitude) R 22964 22965 17863 34816 17863 4202560 31321 2201 0 5 1417 13 0 0 20 0 2 0 28760917 327729152 47343 18446744073709551615 139727165947904 139727170255256 140734872600960 139727056768696 139727123458072 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 17.45
Current children cumulated vsize (KiB) 320048

[startup+21.6002 s]
/proc/loadavg: 1.24 1.11 1.03 1/57 22971
/proc/meminfo: memFree=658756/1022884 swapFree=0/0
[pid=22965] ppid=22964 vsize=320632 CPUtime=18.2
/proc/22965/stat : 22965 (aptitude) R 22964 22965 17863 34816 17863 4202496 54551 2201 295 5 1787 33 0 0 20 0 2 0 28760538 328327168 47701 18446744073709551615 139727165947904 139727170255256 140734872600960 140734872590720 139727123650870 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 322 0 0
/proc/22965/statm: 80158 47701 9749 1052 0 56146 0
[pid=22965/tid=22970] ppid=22964 vsize=320632 CPUtime=14.38
/proc/22965/task/22970/stat : 22970 (aptitude) S 22964 22965 17863 34816 17863 4202560 31458 2201 0 5 1425 13 0 0 20 0 2 0 28760917 328327168 47701 18446744073709551615 139727165947904 139727170255256 140734872600960 139727056775168 139727134692052 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 18.2
Current children cumulated vsize (KiB) 320632

[startup+21.8012 s]
/proc/loadavg: 1.24 1.11 1.03 1/57 22971
/proc/meminfo: memFree=658756/1022884 swapFree=0/0
[pid=22965] ppid=22964 vsize=191096 CPUtime=18.4
/proc/22965/stat : 22965 (aptitude) R 22964 22965 17863 34816 17863 4202496 55285 2700 295 5 1796 43 0 1 20 0 1 0 28760538 195682304 4240 18446744073709551615 139727165947904 139727170255256 140734872600960 140734872600520 139727123813866 0 134217728 4096 0 0 0 0 17 0 0 0 322 0 0
/proc/22965/statm: 47774 4240 1507 1052 0 32030 0
Current children cumulated CPU time (s) 18.4
Current children cumulated vsize (KiB) 191096

Child status: 0
Real time (s): 21.8173
CPU time (s): 18.4252
CPU user time (s): 17.9691
CPU system time (s): 0.456028
CPU usage (%): 84.4519
Max. virtual memory (cumulated for all children) (KiB): 320632

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 17.9691
system time used= 0.456028
maximum resident set size= 191376
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 58050
page faults= 302
swaps= 0
block input operations= 202672
block output operations= 136
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2006
involuntary context switches= 366

runsolver used 0 second user time and 0.112007 second system time

The end