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/11.runsolver.aptitude aptitude -s -y --without-recommends install vcheck libsp-gxmlcpp1 ldapvi python-pyxine nwall 

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.01 0.73 2/55 20911
/proc/meminfo: memFree=910192/1022884 swapFree=0/0
[pid=20911] ppid=20910 vsize=3152 CPUtime=0
/proc/20911/stat : 20911 (runsolver) R 20910 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28292924 3227648 32 18446744073709551615 134512640 134586868 4288100752 4288098800 4151399472 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/20911/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.121999 s]
/proc/loadavg: 1.05 1.01 0.73 2/55 20911
/proc/meminfo: memFree=910192/1022884 swapFree=0/0
[pid=20911] ppid=20910 vsize=89152 CPUtime=0.12
/proc/20911/stat : 20911 (aptitude) R 20910 20911 17863 34816 17863 4202496 7767 1708 0 0 9 2 1 0 20 0 1 0 28292924 91291648 7567 18446744073709551615 140568768913408 140568773220760 140737007122176 140737007113440 140568764314352 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/20911/statm: 22288 7567 6656 1052 0 858 0
Current children cumulated CPU time (s) 0.12
Current children cumulated vsize (KiB) 89152

[startup+0.200305 s]
/proc/loadavg: 1.05 1.01 0.73 2/55 20911
/proc/meminfo: memFree=910192/1022884 swapFree=0/0
[pid=20911] ppid=20910 vsize=89152 CPUtime=0.2
/proc/20911/stat : 20911 (aptitude) R 20910 20911 17863 34816 17863 4202496 7870 1708 0 0 17 2 1 0 20 0 1 0 28292924 91291648 7662 18446744073709551615 140568768913408 140568773220760 140737007122176 140737007111952 140568763766754 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/20911/statm: 22288 7662 6726 1052 0 858 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 89152

[startup+0.300245 s]
/proc/loadavg: 1.05 1.01 0.73 2/55 20911
/proc/meminfo: memFree=910192/1022884 swapFree=0/0
[pid=20911] ppid=20910 vsize=101864 CPUtime=0.29
/proc/20911/stat : 20911 (aptitude) R 20910 20911 17863 34816 17863 4202496 11336 1708 0 0 25 3 1 0 20 0 1 0 28292924 104308736 10383 18446744073709551615 140568768913408 140568773220760 140737007122176 140737007111544 140568771838588 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/20911/statm: 25466 10383 6742 1052 0 4036 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 101864

[startup+0.700216 s]
/proc/loadavg: 1.05 1.01 0.73 2/55 20911
/proc/meminfo: memFree=910192/1022884 swapFree=0/0
[pid=20911] ppid=20910 vsize=110240 CPUtime=0.69
/proc/20911/stat : 20911 (aptitude) R 20910 20911 17863 34816 17863 4202496 12579 1708 0 0 63 5 1 0 20 0 2 0 28292924 112885760 10953 18446744073709551615 140568768913408 140568773220760 140737007122176 140737007114216 140568771509593 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/20911/statm: 27560 10953 6961 1052 0 6130 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 110240

[startup+1.50026 s]
/proc/loadavg: 1.05 1.01 0.73 2/57 20916
/proc/meminfo: memFree=889352/1022884 swapFree=0/0
[pid=20911] ppid=20910 vsize=115424 CPUtime=1.49
/proc/20911/stat : 20911 (aptitude) R 20910 20911 17863 34816 17863 4202496 14141 2207 0 0 140 8 1 0 20 0 2 0 28292924 118194176 12362 18446744073709551615 140568768913408 140568773220760 140737007122176 140737007112888 140568769831124 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/20911/statm: 28856 12362 7060 1052 0 7426 0
[pid=20911/tid=20916] ppid=20910 vsize=115424 CPUtime=0.01
/proc/20911/task/20916/stat : 20916 (aptitude) S 20910 20911 17863 34816 17863 4202560 4 2207 0 0 0 0 1 0 20 0 2 0 28292969 118194176 12362 18446744073709551615 140568768913408 140568773220760 140737007122176 140568672319488 140568737657556 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) 115424

[startup+3.10026 s]
/proc/loadavg: 1.04 1.01 0.74 2/57 20917
/proc/meminfo: memFree=881788/1022884 swapFree=0/0
[pid=20911] ppid=20910 vsize=136412 CPUtime=3.08
/proc/20911/stat : 20911 (aptitude) S 20910 20911 17863 34816 17863 4202496 20789 2207 0 0 295 12 1 0 20 0 2 0 28292924 139685888 17834 18446744073709551615 140568768913408 140568773220760 140737007122176 140737007113936 140568737658443 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/20911/statm: 34103 17834 7129 1052 0 12673 0
[pid=20911/tid=20916] ppid=20910 vsize=136412 CPUtime=1.02
/proc/20911/task/20916/stat : 20916 (aptitude) R 20910 20911 17863 34816 17863 4202560 6135 2207 0 0 97 4 1 0 20 0 2 0 28292969 139685888 17834 18446744073709551615 140568768913408 140568773220760 140737007122176 140568672313624 140568726423979 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 136412

[startup+6.30026 s]
/proc/loadavg: 1.04 1.01 0.74 2/57 20917
/proc/meminfo: memFree=837148/1022884 swapFree=0/0
[pid=20911] ppid=20910 vsize=239372 CPUtime=6.26
/proc/20911/stat : 20911 (aptitude) S 20910 20911 17863 34816 17863 4202496 30117 2207 0 0 611 14 1 0 20 0 2 0 28292924 245116928 27162 18446744073709551615 140568768913408 140568773220760 140737007122176 140737007113936 140568737658443 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/20911/statm: 59843 27162 7129 1052 0 38413 0
[pid=20911/tid=20916] ppid=20910 vsize=239372 CPUtime=4.2
/proc/20911/task/20916/stat : 20916 (aptitude) R 20910 20911 17863 34816 17863 4202560 15462 2207 0 0 413 6 1 0 20 0 2 0 28292969 245116928 27162 18446744073709551615 140568768913408 140568773220760 140737007122176 140568672312920 140568772337978 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) 239372

[startup+12.7003 s]
/proc/loadavg: 1.04 1.01 0.74 2/57 20917
/proc/meminfo: memFree=780356/1022884 swapFree=0/0
[pid=20911] ppid=20910 vsize=292748 CPUtime=12.63
/proc/20911/stat : 20911 (aptitude) S 20910 20911 17863 34816 17863 4202496 43460 2207 0 0 1242 20 1 0 20 0 2 0 28292924 299773952 40502 18446744073709551615 140568768913408 140568773220760 140737007122176 140737007113936 140568737658443 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/20911/statm: 73187 40502 7129 1052 0 51757 0
[pid=20911/tid=20916] ppid=20910 vsize=292748 CPUtime=10.57
/proc/20911/task/20916/stat : 20916 (aptitude) R 20910 20911 17863 34816 17863 4202560 28805 2207 0 0 1044 12 1 0 20 0 2 0 28292969 299773952 40502 18446744073709551615 140568768913408 140568773220760 140737007122176 140568672314408 140568726423885 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.63
Current children cumulated vsize (KiB) 292748

[startup+25.5003 s]
/proc/loadavg: 1.03 1.00 0.74 2/57 20917
/proc/meminfo: memFree=660200/1022884 swapFree=0/0
[pid=20911] ppid=20910 vsize=410172 CPUtime=25.37
/proc/20911/stat : 20911 (aptitude) S 20910 20911 17863 34816 17863 4202496 72813 2207 0 0 2502 34 1 0 20 0 2 0 28292924 420016128 69843 18446744073709551615 140568768913408 140568773220760 140737007122176 140737007113936 140568737658443 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/20911/statm: 102543 69843 7129 1052 0 81113 0
[pid=20911/tid=20916] ppid=20910 vsize=410172 CPUtime=23.31
/proc/20911/task/20916/stat : 20916 (aptitude) R 20910 20911 17863 34816 17863 4202560 58158 2207 0 0 2304 26 1 0 20 0 2 0 28292969 420016128 69843 18446744073709551615 140568768913408 140568773220760 140737007122176 140568672310936 140568727065796 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.37
Current children cumulated vsize (KiB) 410172

[startup+51.1003 s]
/proc/loadavg: 1.02 1.00 0.74 2/57 20917
/proc/meminfo: memFree=499620/1022884 swapFree=0/0
[pid=20911] ppid=20910 vsize=571352 CPUtime=50.85
/proc/20911/stat : 20911 (aptitude) S 20910 20911 17863 34816 17863 4202496 113111 2207 0 0 5033 51 1 0 20 0 2 0 28292924 585064448 110119 18446744073709551615 140568768913408 140568773220760 140737007122176 140737007113936 140568737658443 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/20911/statm: 142838 110119 7143 1052 0 121408 0
[pid=20911/tid=20916] ppid=20910 vsize=571352 CPUtime=48.79
/proc/20911/task/20916/stat : 20916 (aptitude) R 20910 20911 17863 34816 17863 4202560 98449 2207 0 0 4835 43 1 0 20 0 2 0 28292969 585064448 110119 18446744073709551615 140568768913408 140568773220760 140737007122176 140568672313064 140568771656000 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 50.85
Current children cumulated vsize (KiB) 571352

[startup+102.3 s]
/proc/loadavg: 1.01 1.00 0.75 2/57 20917
/proc/meminfo: memFree=269848/1022884 swapFree=0/0
[pid=20911] ppid=20910 vsize=798512 CPUtime=101.82
/proc/20911/stat : 20911 (aptitude) S 20910 20911 17863 34816 17863 4202496 169958 2207 0 0 10091 90 1 0 20 0 2 0 28292924 817676288 166778 18446744073709551615 140568768913408 140568773220760 140737007122176 140737007113936 140568737658443 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/20911/statm: 199628 166778 7143 1052 0 178198 0
[pid=20911/tid=20916] ppid=20910 vsize=798512 CPUtime=99.76
/proc/20911/task/20916/stat : 20916 (aptitude) R 20910 20911 17863 34816 17863 4202560 155296 2207 0 0 9893 82 1 0 20 0 2 0 28292969 817676288 166778 18446744073709551615 140568768913408 140568773220760 140737007122176 140568672313064 140568771559812 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 101.82
Current children cumulated vsize (KiB) 798512

[startup+162.3 s]
/proc/loadavg: 1.00 1.00 0.77 2/57 20917
/proc/meminfo: memFree=40572/1022884 swapFree=0/0
[pid=20911] ppid=20910 vsize=1028788 CPUtime=161.54
/proc/20911/stat : 20911 (aptitude) S 20910 20911 17863 34816 17863 4202496 227646 2207 0 0 16027 126 1 0 20 0 2 0 28292924 1053478912 224425 18446744073709551615 140568768913408 140568773220760 140737007122176 140737007113936 140568737658443 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/20911/statm: 257197 224425 7143 1052 0 235767 0
[pid=20911/tid=20916] ppid=20910 vsize=1028788 CPUtime=159.47
/proc/20911/task/20916/stat : 20916 (aptitude) R 20910 20911 17863 34816 17863 4202560 212984 2207 0 0 15828 118 1 0 20 0 2 0 28292969 1053478912 224425 18446744073709551615 140568768913408 140568773220760 140737007122176 140568672310808 140568771475516 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 161.54
Current children cumulated vsize (KiB) 1028788



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+208.3 s]
/proc/loadavg: 1.50 1.12 0.82 1/58 20918
/proc/meminfo: memFree=8312/1022884 swapFree=0/0
[pid=20911] ppid=20910 vsize=1131104 CPUtime=191.51
/proc/20911/stat : 20911 (aptitude) S 20910 20911 17863 34816 17863 4202496 266048 2207 1164 0 18975 175 1 0 20 0 2 0 28292924 1158250496 247126 18446744073709551615 140568768913408 140568773220760 140737007122176 140737007111952 140568726782419 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1390 0 0
/proc/20911/statm: 282776 247126 5274 1052 0 261339 0
[pid=20918] ppid=20911 vsize=1131104 CPUtime=0
/proc/20918/stat : 20918 (aptitude) D 20911 20911 17863 34816 17863 4202560 29 0 11 0 0 0 0 0 20 0 1 0 28313491 1158250496 241881 18446744073709551615 140568768913408 140568773220760 140737007122176 140737007111936 140568766714695 0 134217728 4096 0 0 0 0 17 0 0 0 77 0 0
/proc/20918/statm: 282776 241881 29 1052 0 261339 0
[pid=20911/tid=20916] ppid=20910 vsize=1131104 CPUtime=185.98
/proc/20911/task/20916/stat : 20916 (aptitude) S 20910 20911 17863 34816 17863 4202560 238743 2207 139 0 18458 139 1 0 20 0 2 0 28292969 1158250496 247126 18446744073709551615 140568768913408 140568773220760 140737007122176 140568672319488 140568737657556 0 134217728 4096 0 0 0 0 -1 0 0 0 122 0 0
Current children cumulated CPU time (s) 191.51
Current children cumulated vsize (KiB) 2262208

Sending Terminated to process tree (bottom up)
Sleeping 2 seconds

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

Child ended because it received signal 15 (SIGTERM)
Real time (s): 209.481
CPU time (s): 191.592
CPU user time (s): 189.784
CPU system time (s): 1.80811
CPU usage (%): 91.4605
Max. virtual memory (cumulated for all children) (KiB): 2262208

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 189.784
system time used= 1.80811
maximum resident set size= 992928
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 268255
page faults= 1164
swaps= 0
block input operations= 67696
block output operations= 176
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1776
involuntary context switches= 3828

runsolver used 0.360022 second user time and 0.64004 second system time

The end