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/logs/84.runsolver.aptitude aptitude -s -y --without-recommends install libcrypt-gpg-perl gtoaster cl-ptester libapache-mod-python2.3 opensc 

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: 0.99 0.74 0.35 2/55 19971
/proc/meminfo: memFree=244084/1022884 swapFree=0/0
[pid=19971] ppid=19970 vsize=54860 CPUtime=0
/proc/19971/stat : 19971 (aptitude) R 19970 19971 17863 34816 17863 4202496 606 0 0 0 0 0 0 0 20 0 1 0 28203660 56176640 506 18446744073709551615 139649034829824 139649039137176 140736881454416 140736881453624 139649032631127 0 0 0 0 0 0 0 17 0 0 0 0 0 0
/proc/19971/statm: 13715 506 414 1052 0 73 0

[startup+0.122022 s]
/proc/loadavg: 0.99 0.74 0.35 2/55 19971
/proc/meminfo: memFree=244084/1022884 swapFree=0/0
[pid=19971] ppid=19970 vsize=80316 CPUtime=0.11
/proc/19971/stat : 19971 (aptitude) R 19970 19971 17863 34816 17863 4202496 5568 1709 0 0 10 1 0 0 20 0 1 0 28203660 82243584 5368 18446744073709551615 139649034829824 139649039137176 140736881454416 140736881445680 139649030230320 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/19971/statm: 20079 5368 4645 1052 0 670 0
Current children cumulated CPU time (s) 0.11
Current children cumulated vsize (KiB) 80316

[startup+0.200282 s]
/proc/loadavg: 0.99 0.74 0.35 2/55 19971
/proc/meminfo: memFree=244084/1022884 swapFree=0/0
[pid=19971] ppid=19970 vsize=90632 CPUtime=0.19
/proc/19971/stat : 19971 (aptitude) R 19970 19971 17863 34816 17863 4202496 8609 1709 0 0 17 2 0 0 20 0 1 0 28203660 92807168 7655 18446744073709551615 139649034829824 139649039137176 140736881454416 140736881443848 139649029730219 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/19971/statm: 22658 7655 4725 1052 0 3249 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 90632

[startup+0.300262 s]
/proc/loadavg: 0.99 0.74 0.35 2/55 19971
/proc/meminfo: memFree=244084/1022884 swapFree=0/0
[pid=19971] ppid=19970 vsize=96684 CPUtime=0.28
/proc/19971/stat : 19971 (aptitude) R 19970 19971 17863 34816 17863 4202496 9022 1709 0 0 26 2 0 0 20 0 2 0 28203660 99004416 7656 18446744073709551615 139649034829824 139649039137176 140736881454416 140736881450200 139649030229928 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19971/statm: 24171 7656 4890 1052 0 4762 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 96684

[startup+0.700196 s]
/proc/loadavg: 0.99 0.74 0.35 2/55 19971
/proc/meminfo: memFree=244084/1022884 swapFree=0/0
[pid=19971] ppid=19970 vsize=100676 CPUtime=0.68
/proc/19971/stat : 19971 (aptitude) R 19970 19971 17863 34816 17863 4202496 10143 1709 0 0 66 2 0 0 20 0 2 0 28203660 103092224 8772 18446744073709551615 139649034829824 139649039137176 140736881454416 140736881444712 139649036458322 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19971/statm: 25169 8772 4995 1052 0 5760 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 100676

[startup+1.50023 s]
/proc/loadavg: 0.99 0.74 0.35 2/57 19977
/proc/meminfo: memFree=228188/1022884 swapFree=0/0
[pid=19971] ppid=19970 vsize=112556 CPUtime=1.49
/proc/19971/stat : 19971 (aptitude) S 19970 19971 17863 34816 17863 4202496 14181 2208 0 0 143 5 0 1 20 0 2 0 28203660 115257344 11839 18446744073709551615 139649034829824 139649039137176 140736881454416 140736881446176 139649003574859 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19971/statm: 28139 11839 5098 1052 0 8730 0
[pid=19971/tid=19976] ppid=19970 vsize=112556 CPUtime=0.34
/proc/19971/task/19976/stat : 19976 (aptitude) R 19970 19971 17863 34816 17863 4202560 3466 2208 0 0 32 1 0 1 20 0 2 0 28203688 115257344 11839 18446744073709551615 139649034829824 139649039137176 140736881454416 139648951402216 139649000762960 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) 112556

[startup+3.10029 s]
/proc/loadavg: 0.99 0.74 0.35 2/57 19977
/proc/meminfo: memFree=207860/1022884 swapFree=0/0
[pid=19971] ppid=19970 vsize=129716 CPUtime=3.07
/proc/19971/stat : 19971 (aptitude) S 19970 19971 17863 34816 17863 4202496 18528 2208 0 0 298 8 0 1 20 0 2 0 28203660 132829184 16149 18446744073709551615 139649034829824 139649039137176 140736881454416 140736881446176 139649003574859 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19971/statm: 32429 16149 5100 1052 0 13020 0
[pid=19971/tid=19976] ppid=19970 vsize=129716 CPUtime=1.93
/proc/19971/task/19976/stat : 19976 (aptitude) R 19970 19971 17863 34816 17863 4202560 7812 2208 0 0 187 5 0 1 20 0 2 0 28203688 132829184 16149 18446744073709551615 139649034829824 139649039137176 140736881454416 139648951402168 139649037426873 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) 129716

[startup+6.30025 s]
/proc/loadavg: 0.99 0.75 0.35 2/57 19977
/proc/meminfo: memFree=180456/1022884 swapFree=0/0
[pid=19971] ppid=19970 vsize=153268 CPUtime=6.26
/proc/19971/stat : 19971 (aptitude) S 19970 19971 17863 34816 17863 4202496 24503 2208 0 0 614 11 0 1 20 0 2 0 28203660 156946432 22035 18446744073709551615 139649034829824 139649039137176 140736881454416 140736881446176 139649003574859 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19971/statm: 38317 22035 5102 1052 0 18908 0
[pid=19971/tid=19976] ppid=19970 vsize=153268 CPUtime=5.12
/proc/19971/task/19976/stat : 19976 (aptitude) R 19970 19971 17863 34816 17863 4202560 13787 2208 0 0 503 8 0 1 20 0 2 0 28203688 156946432 22035 18446744073709551615 139649034829824 139649039137176 140736881454416 139648951402168 139649037506073 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) 153268

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

[startup+6.40032 s]
/proc/loadavg: 0.99 0.75 0.35 2/57 19977
/proc/meminfo: memFree=180456/1022884 swapFree=0/0
[pid=19971] ppid=19970 vsize=154784 CPUtime=6.36
/proc/19971/stat : 19971 (aptitude) S 19970 19971 17863 34816 17863 4202496 24862 2208 0 0 624 11 0 1 20 0 2 0 28203660 158498816 22391 18446744073709551615 139649034829824 139649039137176 140736881454416 140736881446176 139649003574859 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19971/statm: 38696 22391 5103 1052 0 19287 0
[pid=19971/tid=19976] ppid=19970 vsize=154784 CPUtime=5.22
/proc/19971/task/19976/stat : 19976 (aptitude) R 19970 19971 17863 34816 17863 4202560 14146 2208 0 0 513 8 0 1 20 0 2 0 28203688 158498816 22391 18446744073709551615 139649034829824 139649039137176 140736881454416 139648951396968 139649037565575 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.36
Current children cumulated vsize (KiB) 154784

[startup+6.80024 s]
/proc/loadavg: 0.99 0.75 0.35 2/57 19977
/proc/meminfo: memFree=173760/1022884 swapFree=0/0
[pid=19971] ppid=19970 vsize=157080 CPUtime=6.76
/proc/19971/stat : 19971 (aptitude) R 19970 19971 17863 34816 17863 4202496 25505 2208 0 0 664 11 0 1 20 0 2 0 28203660 160849920 23025 18446744073709551615 139649034829824 139649039137176 140736881454416 140736881444552 139649035417344 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19971/statm: 39270 23025 5151 1052 0 19854 0
[pid=19971/tid=19976] ppid=19970 vsize=157080 CPUtime=5.53
/proc/19971/task/19976/stat : 19976 (aptitude) S 19970 19971 17863 34816 17863 4202560 14499 2208 0 0 544 8 0 1 20 0 2 0 28203688 160849920 23025 18446744073709551615 139649034829824 139649039137176 140736881454416 139648951408640 139649003573972 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.76
Current children cumulated vsize (KiB) 157080

[startup+7.00024 s]
/proc/loadavg: 0.99 0.75 0.35 2/57 19977
/proc/meminfo: memFree=173760/1022884 swapFree=0/0
[pid=19971] ppid=19970 vsize=157096 CPUtime=6.96
/proc/19971/stat : 19971 (aptitude) R 19970 19971 17863 34816 17863 4202496 26959 2208 0 0 683 12 0 1 20 0 2 0 28203660 160866304 23041 18446744073709551615 139649034829824 139649039137176 140736881454416 140736881442280 139649037036199 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19971/statm: 39274 23041 5152 1052 0 19858 0
[pid=19971/tid=19976] ppid=19970 vsize=157096 CPUtime=5.53
/proc/19971/task/19976/stat : 19976 (aptitude) S 19970 19971 17863 34816 17863 4202560 14499 2208 0 0 544 8 0 1 20 0 2 0 28203688 160866304 23041 18446744073709551615 139649034829824 139649039137176 140736881454416 139648951408640 139649003573972 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.96
Current children cumulated vsize (KiB) 157096

[startup+7.10101 s]
/proc/loadavg: 0.99 0.75 0.35 2/57 19977
/proc/meminfo: memFree=173760/1022884 swapFree=0/0
[pid=19971] ppid=19970 vsize=134484 CPUtime=7.05
/proc/19971/stat : 19971 (aptitude) R 19970 19971 17863 34816 17863 4202496 27113 2706 0 0 690 14 0 1 20 0 1 0 28203660 137711616 12296 18446744073709551615 139649034829824 139649039137176 140736881454416 140736881453976 139648992695786 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/19971/statm: 33621 12296 1508 1052 0 17877 0
Current children cumulated CPU time (s) 7.05
Current children cumulated vsize (KiB) 134484

Child status: 0
Real time (s): 7.11185
CPU time (s): 7.08444
CPU user time (s): 6.91243
CPU system time (s): 0.17201
CPU usage (%): 99.6147
Max. virtual memory (cumulated for all children) (KiB): 157096

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 6.91243
system time used= 0.17201
maximum resident set size= 92204
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 29886
page faults= 0
swaps= 0
block input operations= 0
block output operations= 112
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 73
involuntary context switches= 181

runsolver used 0.012 second user time and 0.024001 second system time

The end