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/71.runsolver.aptitude aptitude -s -y --without-recommends install spread libffcall1 mirror gcompris cvstrac 

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.13 1.10 1.02 2/55 23774
/proc/meminfo: memFree=953596/1022884 swapFree=0/0
[pid=23774] ppid=23773 vsize=3152 CPUtime=0
/proc/23774/stat : 23774 (runsolver) R 23773 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29045438 3227648 33 18446744073709551615 134512640 134586868 4286632704 4286630752 4151759920 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/23774/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.189914 s]
/proc/loadavg: 1.13 1.10 1.02 2/55 23774
/proc/meminfo: memFree=953596/1022884 swapFree=0/0
[pid=23774] ppid=23773 vsize=40832 CPUtime=0
/proc/23774/stat : 23774 (aptitude) D 23773 23774 17863 34816 17863 4202496 179 0 16 0 0 0 0 0 20 0 1 0 29045438 41811968 102 18446744073709551615 140483040178176 140483044485528 140734606954032 140734606950456 140483038037539 0 0 0 0 0 0 0 17 0 0 0 18 0 0
/proc/23774/statm: 10208 102 63 1052 0 60 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 40832

[startup+0.200388 s]
/proc/loadavg: 1.13 1.10 1.02 2/55 23774
/proc/meminfo: memFree=953596/1022884 swapFree=0/0
[pid=23774] ppid=23773 vsize=40832 CPUtime=0
/proc/23774/stat : 23774 (aptitude) D 23773 23774 17863 34816 17863 4202496 179 0 16 0 0 0 0 0 20 0 1 0 29045438 41811968 102 18446744073709551615 140483040178176 140483044485528 140734606954032 140734606950456 140483038037539 0 0 0 0 0 0 0 17 0 0 0 18 0 0
/proc/23774/statm: 10208 102 63 1052 0 60 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 40832

[startup+0.300387 s]
/proc/loadavg: 1.13 1.10 1.02 2/55 23774
/proc/meminfo: memFree=953596/1022884 swapFree=0/0
[pid=23774] ppid=23773 vsize=57072 CPUtime=0
/proc/23774/stat : 23774 (aptitude) D 23773 23774 17863 34816 17863 4202496 1124 0 25 0 0 0 0 0 20 0 1 0 29045438 58441728 1037 18446744073709551615 140483040178176 140483044485528 140734606954032 140734606947032 140483038037539 0 134217728 4096 0 0 0 0 17 0 0 0 28 0 0
/proc/23774/statm: 14268 1037 865 1052 0 106 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 57072

[startup+0.700331 s]
/proc/loadavg: 1.13 1.10 1.02 2/55 23774
/proc/meminfo: memFree=953596/1022884 swapFree=0/0
[pid=23774] ppid=23773 vsize=100508 CPUtime=0.02
/proc/23774/stat : 23774 (aptitude) D 23773 23774 17863 34816 17863 4202496 3477 1704 80 2 1 1 0 0 20 0 1 0 29045438 102920192 3358 18446744073709551615 140483040178176 140483044485528 140734606954032 140734606945504 140483035228058 0 134217728 4096 0 0 0 0 17 0 0 0 65 0 0
/proc/23774/statm: 25127 3358 2182 1052 0 1122 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 100508

[startup+1.50021 s]
/proc/loadavg: 1.13 1.10 1.02 1/56 23778
/proc/meminfo: memFree=946148/1022884 swapFree=0/0
[pid=23774] ppid=23773 vsize=100508 CPUtime=0.2
/proc/23774/stat : 23774 (aptitude) R 23773 23774 17863 34816 17863 4202496 10403 1704 204 2 17 3 0 0 20 0 1 0 29045438 102920192 10408 18446744073709551615 140483040178176 140483044485528 140734606954032 140734606945296 140482997759789 0 134217728 4096 0 0 0 0 17 0 0 0 126 0 0
/proc/23774/statm: 25127 10408 9232 1052 0 1122 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 100508

[startup+3.10021 s]
/proc/loadavg: 1.13 1.10 1.02 2/56 23778
/proc/meminfo: memFree=877700/1022884 swapFree=0/0
[pid=23774] ppid=23773 vsize=132120 CPUtime=1.22
/proc/23774/stat : 23774 (aptitude) R 23773 23774 17863 34816 17863 4202496 19100 1704 205 2 106 16 0 0 20 0 2 0 29045438 135290880 16576 18446744073709551615 140483040178176 140483044485528 140734606954032 140734606945304 140483043215835 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 185 0 0
/proc/23774/statm: 33030 16576 9548 1052 0 9025 0
Current children cumulated CPU time (s) 1.22
Current children cumulated vsize (KiB) 132120
heavy processes:

[startup+6.30023 s]
/proc/loadavg: 1.12 1.10 1.02 2/57 23780
/proc/meminfo: memFree=829828/1022884 swapFree=0/0
[pid=23774] ppid=23773 vsize=226636 CPUtime=4.39
/proc/23774/stat : 23774 (aptitude) S 23773 23774 17863 34816 17863 4202496 27686 2200 205 4 415 23 1 0 20 0 2 0 29045438 232075264 23997 18446744073709551615 140483040178176 140483044485528 140734606954032 140734606945792 140483008923211 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 185 0 0
/proc/23774/statm: 56659 23997 9700 1052 0 32654 0
[pid=23774/tid=23779] ppid=23773 vsize=226636 CPUtime=1.27
/proc/23774/task/23779/stat : 23779 (aptitude) R 23773 23774 17863 34816 17863 4202560 7289 2200 0 4 124 2 1 0 20 0 2 0 29045693 232075264 23997 18446744073709551615 140483040178176 140483044485528 140734606954032 140482930998968 140483042824474 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.39
Current children cumulated vsize (KiB) 226636
heavy processes:

[startup+12.7003 s]
/proc/loadavg: 1.11 1.10 1.02 2/57 23780
/proc/meminfo: memFree=767084/1022884 swapFree=0/0
[pid=23774] ppid=23773 vsize=276744 CPUtime=10.66
/proc/23774/stat : 23774 (aptitude) R 23773 23774 17863 34816 17863 4202496 41061 2200 218 4 1039 26 1 0 20 0 2 0 29045438 283385856 36651 18446744073709551615 140483040178176 140483044485528 140734606954032 140734606944168 140483042780501 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 193 0 0
/proc/23774/statm: 69186 36651 9748 1052 0 45174 0
[pid=23774/tid=23779] ppid=23773 vsize=276744 CPUtime=7.46
/proc/23774/task/23779/stat : 23779 (aptitude) S 23773 23774 17863 34816 17863 4202560 20463 2200 1 4 740 5 1 0 20 0 2 0 29045693 283385856 36651 18446744073709551615 140483040178176 140483044485528 140734606954032 140482931005440 140483008922324 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0
Current children cumulated CPU time (s) 10.66
Current children cumulated vsize (KiB) 276744

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

[startup+12.8003 s]
/proc/loadavg: 1.11 1.10 1.02 2/57 23780
/proc/meminfo: memFree=767084/1022884 swapFree=0/0
[pid=23774] ppid=23773 vsize=276776 CPUtime=10.76
/proc/23774/stat : 23774 (aptitude) R 23773 23774 17863 34816 17863 4202496 41081 2200 218 4 1049 26 1 0 20 0 2 0 29045438 283418624 36670 18446744073709551615 140483040178176 140483044485528 140734606954032 140734606944168 140482997669458 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 193 0 0
/proc/23774/statm: 69194 36670 9748 1052 0 45182 0
[pid=23774/tid=23779] ppid=23773 vsize=276776 CPUtime=7.46
/proc/23774/task/23779/stat : 23779 (aptitude) S 23773 23774 17863 34816 17863 4202560 20463 2200 1 4 740 5 1 0 20 0 2 0 29045693 283418624 36670 18446744073709551615 140483040178176 140483044485528 140734606954032 140482931005440 140483008922324 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0
Current children cumulated CPU time (s) 10.76
Current children cumulated vsize (KiB) 276776

[startup+13.2002 s]
/proc/loadavg: 1.10 1.10 1.02 2/57 23781
/proc/meminfo: memFree=761744/1022884 swapFree=0/0
[pid=23774] ppid=23773 vsize=276776 CPUtime=11.15
/proc/23774/stat : 23774 (aptitude) R 23773 23774 17863 34816 17863 4202496 43794 2699 218 4 1083 31 1 0 20 0 2 0 29045438 283418624 36775 18446744073709551615 140483040178176 140483044485528 140734606954032 140734606944280 140482998397489 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 193 0 0
/proc/23774/statm: 69194 36775 9749 1052 0 45182 0
[pid=23774/tid=23779] ppid=23773 vsize=276776 CPUtime=7.46
/proc/23774/task/23779/stat : 23779 (aptitude) S 23773 23774 17863 34816 17863 4202560 20463 2699 1 4 740 5 1 0 20 0 2 0 29045693 283418624 36775 18446744073709551615 140483040178176 140483044485528 140734606954032 140482931005440 140483008922324 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0
Current children cumulated CPU time (s) 11.15
Current children cumulated vsize (KiB) 276776

[startup+13.4004 s]
/proc/loadavg: 1.10 1.10 1.02 2/57 23781
/proc/meminfo: memFree=761744/1022884 swapFree=0/0
[pid=23774] ppid=23773 vsize=141872 CPUtime=11.3
/proc/23774/stat : 23774 (aptitude) R 23773 23774 17863 34816 17863 4202496 44397 2699 234 4 1089 40 1 0 20 0 1 0 29045438 145276928 2953 18446744073709551615 140483040178176 140483044485528 140734606954032 140734606953104 140483019839356 0 134217728 4096 0 0 0 0 17 0 0 0 198 0 0
/proc/23774/statm: 35468 2953 1529 1052 0 19724 0
Current children cumulated CPU time (s) 11.3
Current children cumulated vsize (KiB) 141872

Child status: 0
Real time (s): 13.402
CPU time (s): 11.3167
CPU user time (s): 10.9087
CPU system time (s): 0.408025
CPU usage (%): 84.4405
Max. virtual memory (cumulated for all children) (KiB): 276776

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 10.9087
system time used= 0.408025
maximum resident set size= 147436
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 47114
page faults= 239
swaps= 0
block input operations= 168192
block output operations= 136
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1653
involuntary context switches= 249

runsolver used 0.040002 second user time and 0.032002 second system time

The end