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/49.runsolver.aptitude aptitude -s -y --without-recommends install pathogen contact-lookup-applet libdbd-pg-perl exim gnusound 

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.00 1.01 0.93 2/55 21504
/proc/meminfo: memFree=819960/1022884 swapFree=0/0
[pid=21504] ppid=21503 vsize=3152 CPUtime=0
/proc/21504/stat : 21504 (runsolver) R 21503 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28430269 3227648 33 18446744073709551615 134512640 134586868 4287189936 4287187984 4152173616 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/21504/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.199799 s]
/proc/loadavg: 1.00 1.01 0.93 2/55 21504
/proc/meminfo: memFree=819960/1022884 swapFree=0/0
[pid=21504] ppid=21503 vsize=89152 CPUtime=0.18
/proc/21504/stat : 21504 (aptitude) R 21503 21504 17863 34816 17863 4202496 7873 1708 0 0 15 3 0 0 20 0 1 0 28430269 91291648 7662 18446744073709551615 140069162938368 140069167245720 140734301398176 140734301387952 140069157787223 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21504/statm: 22288 7662 6726 1052 0 858 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 89152

[startup+0.200312 s]
/proc/loadavg: 1.00 1.01 0.93 2/55 21504
/proc/meminfo: memFree=819960/1022884 swapFree=0/0
[pid=21504] ppid=21503 vsize=89152 CPUtime=0.18
/proc/21504/stat : 21504 (aptitude) R 21503 21504 17863 34816 17863 4202496 7873 1708 0 0 15 3 0 0 20 0 1 0 28430269 91291648 7662 18446744073709551615 140069162938368 140069167245720 140734301398176 140734301387952 140069157786833 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21504/statm: 22288 7662 6726 1052 0 858 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 89152

[startup+0.300191 s]
/proc/loadavg: 1.00 1.01 0.93 2/55 21504
/proc/meminfo: memFree=819960/1022884 swapFree=0/0
[pid=21504] ppid=21503 vsize=101864 CPUtime=0.29
/proc/21504/stat : 21504 (aptitude) R 21503 21504 17863 34816 17863 4202496 11712 1708 0 0 24 5 0 0 20 0 1 0 28430269 104308736 10756 18446744073709551615 140069162938368 140069167245720 140734301398176 140734301387608 140069157837608 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21504/statm: 25466 10756 6746 1052 0 4036 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 101864

[startup+0.700213 s]
/proc/loadavg: 1.00 1.01 0.93 2/55 21504
/proc/meminfo: memFree=819960/1022884 swapFree=0/0
[pid=21504] ppid=21503 vsize=108268 CPUtime=0.69
/proc/21504/stat : 21504 (aptitude) R 21503 21504 17863 34816 17863 4202496 12217 1708 0 0 63 6 0 0 20 0 2 0 28430269 110866432 10589 18446744073709551615 140069162938368 140069167245720 140734301398176 140734301393672 140069165063722 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21504/statm: 27067 10589 6925 1052 0 5637 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 108268

[startup+1.50034 s]
/proc/loadavg: 1.00 1.01 0.93 2/57 21509
/proc/meminfo: memFree=799120/1022884 swapFree=0/0
[pid=21504] ppid=21503 vsize=115428 CPUtime=1.48
/proc/21504/stat : 21504 (aptitude) R 21503 21504 17863 34816 17863 4202496 14117 2209 0 0 140 7 0 1 20 0 2 0 28430269 118198272 12353 18446744073709551615 140069162938368 140069167245720 140734301398176 140734301389336 140069120448839 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21504/statm: 28857 12353 7057 1052 0 7427 0
[pid=21504/tid=21509] ppid=21503 vsize=115428 CPUtime=0.01
/proc/21504/task/21509/stat : 21509 (aptitude) S 21503 21504 17863 34816 17863 4202560 4 2209 0 0 0 0 0 1 20 0 2 0 28430314 118198272 12353 18446744073709551615 140069162938368 140069167245720 140734301398176 140069066344448 140069131682516 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) 115428

[startup+3.10024 s]
/proc/loadavg: 1.00 1.01 0.93 2/57 21510
/proc/meminfo: memFree=791060/1022884 swapFree=0/0
[pid=21504] ppid=21503 vsize=202216 CPUtime=3.08
/proc/21504/stat : 21504 (aptitude) S 21503 21504 17863 34816 17863 4202496 20837 2209 0 0 297 10 0 1 20 0 2 0 28430269 207069184 17878 18446744073709551615 140069162938368 140069167245720 140734301398176 140734301389936 140069131683403 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21504/statm: 50554 17878 7129 1052 0 29124 0
[pid=21504/tid=21509] ppid=21503 vsize=202216 CPUtime=1.03
/proc/21504/task/21509/stat : 21509 (aptitude) R 21503 21504 17863 34816 17863 4202560 6171 2209 0 0 99 3 0 1 20 0 2 0 28430314 207069184 17878 18446744073709551615 140069162938368 140069167245720 140734301398176 140069066335768 140069165149274 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) 202216

[startup+6.30024 s]
/proc/loadavg: 1.00 1.01 0.93 2/57 21510
/proc/meminfo: memFree=755348/1022884 swapFree=0/0
[pid=21504] ppid=21503 vsize=231408 CPUtime=6.26
/proc/21504/stat : 21504 (aptitude) S 21503 21504 17863 34816 17863 4202496 28128 2209 0 0 610 15 0 1 20 0 2 0 28430269 236961792 25169 18446744073709551615 140069162938368 140069167245720 140734301398176 140734301389936 140069131683403 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21504/statm: 57852 25169 7130 1052 0 36422 0
[pid=21504/tid=21509] ppid=21503 vsize=231408 CPUtime=4.21
/proc/21504/task/21509/stat : 21509 (aptitude) R 21503 21504 17863 34816 17863 4202560 13462 2209 0 0 412 8 0 1 20 0 2 0 28430314 236961792 25169 18446744073709551615 140069162938368 140069167245720 140734301398176 140069066337976 140069165712549 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) 231408

[startup+12.7002 s]
/proc/loadavg: 1.00 1.01 0.93 2/57 21510
/proc/meminfo: memFree=688388/1022884 swapFree=0/0
[pid=21504] ppid=21503 vsize=295916 CPUtime=12.63
/proc/21504/stat : 21504 (aptitude) S 21503 21504 17863 34816 17863 4202496 44289 2209 0 0 1242 20 0 1 20 0 2 0 28430269 303017984 41317 18446744073709551615 140069162938368 140069167245720 140734301398176 140734301389936 140069131683403 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21504/statm: 73979 41317 7130 1052 0 52549 0
[pid=21504/tid=21509] ppid=21503 vsize=295916 CPUtime=10.58
/proc/21504/task/21509/stat : 21509 (aptitude) R 21503 21504 17863 34816 17863 4202560 29623 2209 0 0 1044 13 0 1 20 0 2 0 28430314 303017984 41317 18446744073709551615 140069162938368 140069167245720 140734301398176 140069066337976 140069120438544 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) 295916

[startup+25.5003 s]
/proc/loadavg: 1.00 1.01 0.93 2/57 21510
/proc/meminfo: memFree=594148/1022884 swapFree=0/0
[pid=21504] ppid=21503 vsize=385404 CPUtime=25.37
/proc/21504/stat : 21504 (aptitude) S 21503 21504 17863 34816 17863 4202496 66838 2209 0 0 2500 36 0 1 20 0 2 0 28430269 394653696 63658 18446744073709551615 140069162938368 140069167245720 140734301398176 140734301389936 140069131683403 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21504/statm: 96351 63658 7130 1052 0 74921 0
[pid=21504/tid=21509] ppid=21503 vsize=385404 CPUtime=23.32
/proc/21504/task/21509/stat : 21509 (aptitude) R 21503 21504 17863 34816 17863 4202560 52172 2209 0 0 2302 29 0 1 20 0 2 0 28430314 394653696 63658 18446744073709551615 140069162938368 140069167245720 140734301398176 140069066337928 140069165645733 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) 385404

[startup+51.1003 s]
/proc/loadavg: 1.00 1.01 0.93 2/57 21510
/proc/meminfo: memFree=471140/1022884 swapFree=0/0
[pid=21504] ppid=21503 vsize=509964 CPUtime=50.86
/proc/21504/stat : 21504 (aptitude) S 21503 21504 17863 34816 17863 4202496 97943 2209 0 0 5033 52 0 1 20 0 2 0 28430269 522203136 94761 18446744073709551615 140069162938368 140069167245720 140734301398176 140734301389936 140069131683403 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21504/statm: 127491 94761 7144 1052 0 106061 0
[pid=21504/tid=21509] ppid=21503 vsize=509964 CPUtime=48.81
/proc/21504/task/21509/stat : 21509 (aptitude) R 21503 21504 17863 34816 17863 4202560 83270 2209 0 0 4835 45 0 1 20 0 2 0 28430314 522203136 94761 18446744073709551615 140069162938368 140069167245720 140734301398176 140069066337976 140069165677475 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 50.86
Current children cumulated vsize (KiB) 509964

[startup+102.3 s]
/proc/loadavg: 1.00 1.00 0.93 2/57 21510
/proc/meminfo: memFree=259224/1022884 swapFree=0/0
[pid=21504] ppid=21503 vsize=719164 CPUtime=101.83
/proc/21504/stat : 21504 (aptitude) S 21503 21504 17863 34816 17863 4202496 150187 2209 0 0 10099 83 0 1 20 0 2 0 28430269 736423936 146942 18446744073709551615 140069162938368 140069167245720 140734301398176 140734301389936 140069131683403 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21504/statm: 179791 146942 7144 1052 0 158361 0
[pid=21504/tid=21509] ppid=21503 vsize=719164 CPUtime=99.77
/proc/21504/task/21509/stat : 21509 (aptitude) R 21503 21504 17863 34816 17863 4202560 135514 2209 0 0 9900 76 0 1 20 0 2 0 28430314 736423936 146942 18446744073709551615 140069162938368 140069167245720 140734301398176 140069066335720 140069165680954 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 101.83
Current children cumulated vsize (KiB) 719164

[startup+162.3 s]
/proc/loadavg: 1.16 1.03 0.94 1/57 21510
/proc/meminfo: memFree=8280/1022884 swapFree=0/0
[pid=21504] ppid=21503 vsize=1005428 CPUtime=159.04
/proc/21504/stat : 21504 (aptitude) S 21503 21504 17863 34816 17863 4202496 221870 2209 0 0 15779 124 0 1 20 0 2 0 28430269 1029558272 218018 18446744073709551615 140069162938368 140069167245720 140734301398176 140734301389936 140069131683403 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21504/statm: 251357 218018 6581 1052 0 229927 0
[pid=21504/tid=21509] ppid=21503 vsize=1005428 CPUtime=156.98
/proc/21504/task/21509/stat : 21509 (aptitude) R 21503 21504 17863 34816 17863 4202560 207197 2209 0 0 15580 117 0 1 20 0 2 0 28430314 1029558272 218018 18446744073709551615 140069162938368 140069167245720 140734301398176 140069066338696 140069165606462 0 134217728 4096 0 0 0 0 -1 0 0 0 246 0 0
Current children cumulated CPU time (s) 159.04
Current children cumulated vsize (KiB) 1005428



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+188.7 s]
/proc/loadavg: 1.16 1.04 0.94 2/57 21510
/proc/meminfo: memFree=10124/1022884 swapFree=0/0
[pid=21504] ppid=21503 vsize=1151024 CPUtime=177.48
/proc/21504/stat : 21504 (aptitude) S 21503 21504 17863 34816 17863 4202496 263896 2209 1092 0 17592 155 0 1 20 0 2 0 28430269 1178648576 229380 18446744073709551615 140069162938368 140069167245720 140734301398176 140734301389936 140069131683403 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21504/statm: 287756 229380 5847 1052 0 266326 0
[pid=21504/tid=21509] ppid=21503 vsize=1151024 CPUtime=175.42
/proc/21504/task/21509/stat : 21509 (aptitude) R 21503 21504 17863 34816 17863 4202560 249223 2209 1092 0 17393 148 0 1 20 0 2 0 28430314 1178648576 229380 18446744073709551615 140069162938368 140069167245720 140734301398176 140069066335768 140069165167322 0 134217728 4096 0 0 0 0 -1 0 0 0 977 0 0
Current children cumulated CPU time (s) 177.48
Current children cumulated vsize (KiB) 1151024

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

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

[startup+188.7 s]
/proc/loadavg: 1.16 1.04 0.94 2/57 21510
/proc/meminfo: memFree=10124/1022884 swapFree=0/0
[pid=21504] ppid=21503 vsize=1151024 CPUtime=177.48
/proc/21504/stat : 21504 (aptitude) S 21503 21504 17863 34816 17863 4202496 263896 2209 1092 0 17592 155 0 1 20 0 2 0 28430269 1178648576 229380 18446744073709551615 140069162938368 140069167245720 140734301398176 140734301389936 140069131683403 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21504/statm: 287756 229380 5847 1052 0 266326 0
[pid=21504/tid=21509] ppid=21503 vsize=1151024 CPUtime=175.42
/proc/21504/task/21509/stat : 21509 (aptitude) R 21503 21504 17863 34816 17863 4202560 249223 2209 1092 0 17393 148 0 1 20 0 2 0 28430314 1178648576 229380 18446744073709551615 140069162938368 140069167245720 140734301398176 140069066335768 140069165167322 0 134217728 4096 0 0 0 0 -1 0 0 0 977 0 0
Current children cumulated CPU time (s) 177.48
Current children cumulated vsize (KiB) 1151024

Child ended because it received signal 15 (SIGTERM)
Real time (s): 188.937
CPU time (s): 177.611
CPU user time (s): 175.971
CPU system time (s): 1.6401
CPU usage (%): 94.0053
Max. virtual memory (cumulated for all children) (KiB): 1151024

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 175.971
system time used= 1.6401
maximum resident set size= 937928
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 266207
page faults= 1101
swaps= 0
block input operations= 69384
block output operations= 56
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1589
involuntary context switches= 4949

runsolver used 0.256016 second user time and 0.612038 second system time

The end