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/27.runsolver.aptitude aptitude -s -y --without-recommends install xpdf-common planner regina3-dev isdnutils-doc mailagent 

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.03 0.86 2/55 21074
/proc/meminfo: memFree=904248/1022884 swapFree=0/0
[pid=21074] ppid=21073 vsize=3152 CPUtime=0
/proc/21074/stat : 21074 (runsolver) R 21073 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28355704 3227648 32 18446744073709551615 134512640 134586868 4293580032 4293578080 4151981104 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/21074/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.132331 s]
/proc/loadavg: 1.00 1.03 0.86 2/55 21074
/proc/meminfo: memFree=904248/1022884 swapFree=0/0
[pid=21074] ppid=21073 vsize=89152 CPUtime=0.12
/proc/21074/stat : 21074 (aptitude) R 21073 21074 17863 34816 17863 4202496 7770 1708 0 0 9 3 0 0 20 0 1 0 28355704 91291648 7570 18446744073709551615 139679452090368 139679456397720 140735941417344 140735941408608 139679446935301 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21074/statm: 22288 7570 6659 1052 0 858 0
Current children cumulated CPU time (s) 0.12
Current children cumulated vsize (KiB) 89152

[startup+0.200288 s]
/proc/loadavg: 1.00 1.03 0.86 2/55 21074
/proc/meminfo: memFree=904248/1022884 swapFree=0/0
[pid=21074] ppid=21073 vsize=89152 CPUtime=0.18
/proc/21074/stat : 21074 (aptitude) R 21073 21074 17863 34816 17863 4202496 7870 1708 0 0 15 3 0 0 20 0 1 0 28355704 91291648 7662 18446744073709551615 139679452090368 139679456397720 140735941417344 140735941407120 139679409672112 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21074/statm: 22288 7662 6726 1052 0 858 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 89152

[startup+0.30028 s]
/proc/loadavg: 1.00 1.03 0.86 2/55 21074
/proc/meminfo: memFree=904248/1022884 swapFree=0/0
[pid=21074] ppid=21073 vsize=101864 CPUtime=0.28
/proc/21074/stat : 21074 (aptitude) R 21073 21074 17863 34816 17863 4202496 11709 1708 0 0 24 4 0 0 20 0 1 0 28355704 104308736 10756 18446744073709551615 139679452090368 139679456397720 140735941417344 140735941406776 139679446990726 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21074/statm: 25466 10756 6746 1052 0 4036 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 101864

[startup+0.700199 s]
/proc/loadavg: 1.00 1.03 0.86 2/55 21074
/proc/meminfo: memFree=904248/1022884 swapFree=0/0
[pid=21074] ppid=21073 vsize=110220 CPUtime=0.68
/proc/21074/stat : 21074 (aptitude) R 21073 21074 17863 34816 17863 4202496 12692 1708 0 0 63 5 0 0 20 0 2 0 28355704 112865280 11064 18446744073709551615 139679452090368 139679456397720 140735941417344 140735941409384 139679454686553 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21074/statm: 27555 11064 6961 1052 0 6125 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 110220

[startup+1.50024 s]
/proc/loadavg: 1.00 1.03 0.86 2/57 21079
/proc/meminfo: memFree=883408/1022884 swapFree=0/0
[pid=21074] ppid=21073 vsize=115464 CPUtime=1.47
/proc/21074/stat : 21074 (aptitude) R 21073 21074 17863 34816 17863 4202496 14563 2207 0 0 138 9 0 0 20 0 2 0 28355704 118235136 12359 18446744073709551615 139679452090368 139679456397720 140735941417344 140735941409368 139679409586078 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21074/statm: 28866 12359 7073 1052 0 7436 0
[pid=21074/tid=21079] ppid=21073 vsize=115464 CPUtime=0
/proc/21074/task/21079/stat : 21079 (aptitude) S 21073 21074 17863 34816 17863 4202560 6 2207 0 0 0 0 0 0 20 0 2 0 28355748 118235136 12359 18446744073709551615 139679452090368 139679456397720 140735941417344 139679355496448 139679420834516 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 115464

[startup+3.10024 s]
/proc/loadavg: 1.00 1.03 0.86 2/57 21080
/proc/meminfo: memFree=876464/1022884 swapFree=0/0
[pid=21074] ppid=21073 vsize=136728 CPUtime=3.07
/proc/21074/stat : 21074 (aptitude) S 21073 21074 17863 34816 17863 4202496 20863 2207 0 0 297 10 0 0 20 0 2 0 28355704 140009472 17899 18446744073709551615 139679452090368 139679456397720 140735941417344 140735941409104 139679420835403 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21074/statm: 34182 17899 7129 1052 0 12752 0
[pid=21074/tid=21079] ppid=21073 vsize=136728 CPUtime=1.05
/proc/21074/task/21079/stat : 21079 (aptitude) R 21073 21074 17863 34816 17863 4202560 6219 2207 0 0 104 1 0 0 20 0 2 0 28355748 140009472 17899 18446744073709551615 139679452090368 139679456397720 140735941417344 139679355489880 139679453718885 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) 136728

[startup+6.30024 s]
/proc/loadavg: 1.00 1.03 0.87 2/57 21080
/proc/meminfo: memFree=827608/1022884 swapFree=0/0
[pid=21074] ppid=21073 vsize=246564 CPUtime=6.25
/proc/21074/stat : 21074 (aptitude) S 21073 21074 17863 34816 17863 4202496 31948 2207 0 0 612 13 0 0 20 0 2 0 28355704 252481536 28977 18446744073709551615 139679452090368 139679456397720 140735941417344 140735941409104 139679420835403 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21074/statm: 61641 28977 7129 1052 0 40211 0
[pid=21074/tid=21079] ppid=21073 vsize=246564 CPUtime=4.23
/proc/21074/task/21079/stat : 21079 (aptitude) R 21073 21074 17863 34816 17863 4202560 17303 2207 0 0 419 4 0 0 20 0 2 0 28355748 252481536 28977 18446744073709551615 139679452090368 139679456397720 140735941417344 139679355488120 139679454725917 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.25
Current children cumulated vsize (KiB) 246564

[startup+12.7002 s]
/proc/loadavg: 1.00 1.03 0.87 2/57 21080
/proc/meminfo: memFree=768460/1022884 swapFree=0/0
[pid=21074] ppid=21073 vsize=297672 CPUtime=12.62
/proc/21074/stat : 21074 (aptitude) S 21073 21074 17863 34816 17863 4202496 44751 2207 0 0 1242 20 0 0 20 0 2 0 28355704 304816128 41755 18446744073709551615 139679452090368 139679456397720 140735941417344 140735941409104 139679420835403 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21074/statm: 74418 41755 7129 1052 0 52988 0
[pid=21074/tid=21079] ppid=21073 vsize=297672 CPUtime=10.6
/proc/21074/task/21079/stat : 21079 (aptitude) R 21073 21074 17863 34816 17863 4202560 30106 2207 0 0 1049 11 0 0 20 0 2 0 28355748 304816128 41755 18446744073709551615 139679452090368 139679456397720 140735941417344 139679355490152 139679454864435 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.62
Current children cumulated vsize (KiB) 297672

[startup+25.5003 s]
/proc/loadavg: 1.00 1.02 0.87 2/57 21080
/proc/meminfo: memFree=699516/1022884 swapFree=0/0
[pid=21074] ppid=21073 vsize=364276 CPUtime=25.36
/proc/21074/stat : 21074 (aptitude) S 21073 21074 17863 34816 17863 4202496 61558 2207 0 0 2506 30 0 0 20 0 2 0 28355704 373018624 58373 18446744073709551615 139679452090368 139679456397720 140735941417344 140735941409104 139679420835403 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21074/statm: 91069 58373 7129 1052 0 69639 0
[pid=21074/tid=21079] ppid=21073 vsize=364276 CPUtime=23.33
/proc/21074/task/21079/stat : 21079 (aptitude) R 21073 21074 17863 34816 17863 4202560 46913 2207 0 0 2312 21 0 0 20 0 2 0 28355748 373018624 58373 18446744073709551615 139679452090368 139679456397720 140735941417344 139679355489976 139679454661012 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.36
Current children cumulated vsize (KiB) 364276

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

[startup+25.6003 s]
/proc/loadavg: 1.00 1.02 0.87 2/57 21080
/proc/meminfo: memFree=699516/1022884 swapFree=0/0
[pid=21074] ppid=21073 vsize=364940 CPUtime=25.46
/proc/21074/stat : 21074 (aptitude) S 21073 21074 17863 34816 17863 4202496 61700 2207 0 0 2516 30 0 0 20 0 2 0 28355704 373698560 58515 18446744073709551615 139679452090368 139679456397720 140735941417344 140735941409104 139679420835403 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21074/statm: 91235 58515 7129 1052 0 69805 0
[pid=21074/tid=21079] ppid=21073 vsize=364940 CPUtime=23.43
/proc/21074/task/21079/stat : 21079 (aptitude) R 21073 21074 17863 34816 17863 4202560 47055 2207 0 0 2322 21 0 0 20 0 2 0 28355748 373698560 58515 18446744073709551615 139679452090368 139679456397720 140735941417344 139679355489976 139679409600608 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.46
Current children cumulated vsize (KiB) 364940

[startup+38.4002 s]
/proc/loadavg: 1.00 1.02 0.87 2/57 21080
/proc/meminfo: memFree=645452/1022884 swapFree=0/0
[pid=21074] ppid=21073 vsize=421452 CPUtime=38.21
/proc/21074/stat : 21074 (aptitude) S 21073 21074 17863 34816 17863 4202496 75924 2207 0 0 3783 38 0 0 20 0 2 0 28355704 431566848 72699 18446744073709551615 139679452090368 139679456397720 140735941417344 140735941409104 139679420835403 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21074/statm: 105363 72699 7143 1052 0 83933 0
[pid=21074/tid=21079] ppid=21073 vsize=421452 CPUtime=36.18
/proc/21074/task/21079/stat : 21079 (aptitude) R 21073 21074 17863 34816 17863 4202560 61272 2207 0 0 3589 29 0 0 20 0 2 0 28355748 431566848 72699 18446744073709551615 139679452090368 139679456397720 140735941417344 139679355487768 139679409671918 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 38.21
Current children cumulated vsize (KiB) 421452

[startup+41.6002 s]
/proc/loadavg: 1.00 1.02 0.87 2/57 21080
/proc/meminfo: memFree=631936/1022884 swapFree=0/0
[pid=21074] ppid=21073 vsize=435104 CPUtime=41.39
/proc/21074/stat : 21074 (aptitude) S 21073 21074 17863 34816 17863 4202496 79328 2207 0 0 4099 40 0 0 20 0 2 0 28355704 445546496 76103 18446744073709551615 139679452090368 139679456397720 140735941417344 140735941409104 139679420835403 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21074/statm: 108776 76103 7143 1052 0 87346 0
[pid=21074/tid=21079] ppid=21073 vsize=435104 CPUtime=39.37
/proc/21074/task/21079/stat : 21079 (aptitude) R 21073 21074 17863 34816 17863 4202560 64676 2207 0 0 3906 31 0 0 20 0 2 0 28355748 445546496 76103 18446744073709551615 139679452090368 139679456397720 140735941417344 139679355489928 139679454789151 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 41.39
Current children cumulated vsize (KiB) 435104

[startup+44.8002 s]
/proc/loadavg: 1.00 1.02 0.87 2/57 21080
/proc/meminfo: memFree=615940/1022884 swapFree=0/0
[pid=21074] ppid=21073 vsize=450476 CPUtime=44.58
/proc/21074/stat : 21074 (aptitude) S 21073 21074 17863 34816 17863 4202496 83179 2207 0 0 4417 41 0 0 20 0 2 0 28355704 461287424 79947 18446744073709551615 139679452090368 139679456397720 140735941417344 140735941409104 139679420835403 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21074/statm: 112619 79947 7143 1052 0 91189 0
[pid=21074/tid=21079] ppid=21073 vsize=450476 CPUtime=42.55
/proc/21074/task/21079/stat : 21079 (aptitude) R 21073 21074 17863 34816 17863 4202560 68527 2207 0 0 4223 32 0 0 20 0 2 0 28355748 461287424 79947 18446744073709551615 139679452090368 139679456397720 140735941417344 139679355487720 139679446924384 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 44.58
Current children cumulated vsize (KiB) 450476

[startup+46.4002 s]
/proc/loadavg: 1.00 1.02 0.87 2/57 21080
/proc/meminfo: memFree=605772/1022884 swapFree=0/0
[pid=21074] ppid=21073 vsize=455740 CPUtime=46.17
/proc/21074/stat : 21074 (aptitude) R 21073 21074 17863 34816 17863 4202496 84829 2207 0 0 4575 42 0 0 20 0 2 0 28355704 466677760 81473 18446744073709551615 139679452090368 139679456397720 140735941417344 140735941407480 139679409581630 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21074/statm: 113935 81473 7191 1052 0 92498 0
[pid=21074/tid=21079] ppid=21073 vsize=455740 CPUtime=43.64
/proc/21074/task/21079/stat : 21079 (aptitude) S 21073 21074 17863 34816 17863 4202560 69810 2207 0 0 4332 32 0 0 20 0 2 0 28355748 466677760 81473 18446744073709551615 139679452090368 139679456397720 140735941417344 139679355496448 139679420834516 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 46.17
Current children cumulated vsize (KiB) 455740

[startup+46.8002 s]
/proc/loadavg: 1.00 1.02 0.87 2/57 21080
/proc/meminfo: memFree=605772/1022884 swapFree=0/0
[pid=21074] ppid=21073 vsize=455740 CPUtime=46.57
/proc/21074/stat : 21074 (aptitude) R 21073 21074 17863 34816 17863 4202496 85512 2207 0 0 4615 42 0 0 20 0 2 0 28355704 466677760 81474 18446744073709551615 139679452090368 139679456397720 140735941417344 140735941407176 139679446932941 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21074/statm: 113935 81474 7192 1052 0 92498 0
[pid=21074/tid=21079] ppid=21073 vsize=455740 CPUtime=43.64
/proc/21074/task/21079/stat : 21079 (aptitude) S 21073 21074 17863 34816 17863 4202560 69810 2207 0 0 4332 32 0 0 20 0 2 0 28355748 466677760 81474 18446744073709551615 139679452090368 139679456397720 140735941417344 139679355496448 139679420834516 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 46.57
Current children cumulated vsize (KiB) 455740

[startup+47.0002 s]
/proc/loadavg: 1.00 1.02 0.87 2/57 21080
/proc/meminfo: memFree=605772/1022884 swapFree=0/0
[pid=21074] ppid=21073 vsize=455740 CPUtime=46.77
/proc/21074/stat : 21074 (aptitude) R 21073 21074 17863 34816 17863 4202496 86762 2207 0 0 4630 47 0 0 20 0 2 0 28355704 466677760 81465 18446744073709551615 139679452090368 139679456397720 140735941417344 140735941407104 139679409793334 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21074/statm: 113935 81465 7192 1052 0 92498 0
[pid=21074/tid=21079] ppid=21073 vsize=455740 CPUtime=43.64
/proc/21074/task/21079/stat : 21079 (aptitude) S 21073 21074 17863 34816 17863 4202560 69810 2207 0 0 4332 32 0 0 20 0 2 0 28355748 466677760 81465 18446744073709551615 139679452090368 139679456397720 140735941417344 139679355496448 139679420834516 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 46.77
Current children cumulated vsize (KiB) 455740

[startup+47.101 s]
/proc/loadavg: 1.00 1.02 0.87 2/57 21080
/proc/meminfo: memFree=605772/1022884 swapFree=0/0
[pid=21074] ppid=21073 vsize=283416 CPUtime=46.88
/proc/21074/stat : 21074 (aptitude) R 21073 21074 17863 34816 17863 4202496 87535 2706 0 0 4632 54 0 2 20 0 1 0 28355704 290217984 30139 18446744073709551615 139679452090368 139679456397720 140735941417344 140735941416904 139679409956330 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21074/statm: 70854 30139 1521 1052 0 55110 0
Current children cumulated CPU time (s) 46.88
Current children cumulated vsize (KiB) 283416

Child status: 0
Real time (s): 47.1301
CPU time (s): 46.9269
CPU user time (s): 46.3309
CPU system time (s): 0.596037
CPU usage (%): 99.5689
Max. virtual memory (cumulated for all children) (KiB): 455740

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 46.3309
system time used= 0.596037
maximum resident set size= 326236
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 90308
page faults= 0
swaps= 0
block input operations= 0
block output operations= 144
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 155
involuntary context switches= 856

runsolver used 0.024001 second user time and 0.188011 second system time

The end