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: /home/misc2010/bin/runsolver -s SIGUSR1 -M 1124 -C 290 -d 10 -w /home/misc2010/tmp/201012070034/aptitude-trendy-1.0/rand165.sarge-etch.cudf.sarge-etch.log.runsolver ./aptitude-trendy-1.0 /home/misc2010/data/icse/sarge-etch/rand165.sarge-etch.cudf /home/misc2010/tmp/201012070034/aptitude-trendy-1.0/rand165.sarge-etch.cudf.sarge-etch.result 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 290 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 320 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.98 0.99 3/41 8881
/proc/meminfo: memFree=788392/1048576 swapFree=2080288/2097144
[pid=8880] ppid=8879 vsize=2576 CPUtime=0
/proc/8880/stat : 8880 (aptitude-trendy) R 8879 8880 4159 34819 4229 4202496 360 0 0 0 0 0 0 0 25 0 1 0 878791856 2637824 273 1283457024 134512640 135304128 4292741104 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/8880/statm: 644 273 232 194 0 30 0
[pid=8881] ppid=8880 vsize=2576 CPUtime=0
/proc/8881/stat : 8881 (aptitude-trendy) R 8880 8880 4159 34819 4229 4202560 0 0 0 0 0 0 0 0 25 0 1 0 878791856 2637824 41 1283457024 134512640 135304128 4292741104 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/8881/statm: 644 41 0 194 0 30 0

[startup+0.152882 s]
/proc/loadavg: 0.99 0.98 0.99 3/41 8881
/proc/meminfo: memFree=788392/1048576 swapFree=2080288/2097144
[pid=8880] ppid=8879 vsize=2588 CPUtime=0.02
/proc/8880/stat : 8880 (aptitude-trendy) S 8879 8880 4159 34819 4229 4202496 567 1858 0 0 0 0 0 2 25 0 1 0 878791856 2650112 284 1283457024 134512640 135304128 4292741104 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8880/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2588

[startup+0.202895 s]
/proc/loadavg: 0.99 0.98 0.99 3/41 8881
/proc/meminfo: memFree=788392/1048576 swapFree=2080288/2097144
[pid=8880] ppid=8879 vsize=2588 CPUtime=0.02
/proc/8880/stat : 8880 (aptitude-trendy) S 8879 8880 4159 34819 4229 4202496 567 1858 0 0 0 0 0 2 25 0 1 0 878791856 2650112 284 1283457024 134512640 135304128 4292741104 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8880/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2588

[startup+0.312926 s]
/proc/loadavg: 0.99 0.98 0.99 3/41 8881
/proc/meminfo: memFree=788392/1048576 swapFree=2080288/2097144
[pid=8880] ppid=8879 vsize=2588 CPUtime=0.02
/proc/8880/stat : 8880 (aptitude-trendy) S 8879 8880 4159 34819 4229 4202496 567 1858 0 0 0 0 0 2 25 0 1 0 878791856 2650112 284 1283457024 134512640 135304128 4292741104 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8880/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2588

[startup+0.713014 s]
/proc/loadavg: 0.99 0.98 0.99 3/41 8881
/proc/meminfo: memFree=788392/1048576 swapFree=2080288/2097144
[pid=8880] ppid=8879 vsize=2588 CPUtime=0.02
/proc/8880/stat : 8880 (aptitude-trendy) S 8879 8880 4159 34819 4229 4202496 567 1858 0 0 0 0 0 2 25 0 1 0 878791856 2650112 284 1283457024 134512640 135304128 4292741104 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8880/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2588

[startup+1.51324 s]
/proc/loadavg: 0.99 0.98 0.99 2/42 8891
/proc/meminfo: memFree=758832/1048576 swapFree=2080288/2097144
[pid=8880] ppid=8879 vsize=2588 CPUtime=0.02
/proc/8880/stat : 8880 (aptitude-trendy) S 8879 8880 4159 34819 4229 4202496 567 1858 0 0 0 0 0 2 25 0 1 0 878791856 2650112 284 1283457024 134512640 135304128 4292741104 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8880/statm: 647 284 240 194 0 33 0
[pid=8891] ppid=8880 vsize=33680 CPUtime=1.47
/proc/8891/stat : 8891 (cudftodeb.nativ) R 8880 8880 4159 34819 4229 4202496 8018 0 3 0 143 4 0 0 25 0 1 0 878791859 34488320 7948 1283457024 134512640 135004320 4293881552 18446744073709551615 134933540 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/8891/statm: 8420 7948 236 121 0 7812 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 36268

[startup+3.1137 s]
/proc/loadavg: 0.99 0.98 0.99 2/42 8891
/proc/meminfo: memFree=734032/1048576 swapFree=2080288/2097144
[pid=8880] ppid=8879 vsize=2588 CPUtime=0.02
/proc/8880/stat : 8880 (aptitude-trendy) S 8879 8880 4159 34819 4229 4202496 567 1858 0 0 0 0 0 2 25 0 1 0 878791856 2650112 284 1283457024 134512640 135304128 4292741104 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8880/statm: 647 284 240 194 0 33 0
[pid=8891] ppid=8880 vsize=30240 CPUtime=3.06
/proc/8891/stat : 8891 (cudftodeb.nativ) R 8880 8880 4159 34819 4229 4202496 12431 0 3 0 298 8 0 0 25 0 1 0 878791859 30965760 7115 1283457024 134512640 135004320 4293881552 18446744073709551615 134868871 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/8891/statm: 7560 7115 237 121 0 6952 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 32828

[startup+6.31035 s]
/proc/loadavg: 0.99 0.98 0.99 2/42 8902
/proc/meminfo: memFree=731008/1048576 swapFree=2080288/2097144
[pid=8880] ppid=8879 vsize=2596 CPUtime=3.33
/proc/8880/stat : 8880 (aptitude-trendy) S 8879 8880 4159 34819 4229 4202496 698 17464 0 4 1 0 320 12 18 0 1 0 878791856 2658304 295 1283457024 134512640 135304128 4292741104 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8880/statm: 649 295 249 194 0 35 0
[pid=8901] ppid=8880 vsize=46876 CPUtime=1.36
/proc/8901/stat : 8901 (aptitude) R 8880 8880 4159 34819 4229 4202496 9569 651 167 0 131 5 0 0 20 0 2 0 878792276 48001024 6035 1283457024 134512640 137933492 4293754208 18446744073709551615 136685760 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/8901/statm: 11719 6035 3975 836 0 6128 0
Current children cumulated CPU time (s) 4.69
Current children cumulated vsize (KiB) 49472
heavy processes:

[startup+12.7121 s]
/proc/loadavg: 0.99 0.98 0.99 2/43 8905
/proc/meminfo: memFree=700288/1048576 swapFree=2080288/2097144
[pid=8880] ppid=8879 vsize=2596 CPUtime=3.33
/proc/8880/stat : 8880 (aptitude-trendy) S 8879 8880 4159 34819 4229 4202496 698 17464 0 4 1 0 320 12 18 0 1 0 878791856 2658304 295 1283457024 134512640 135304128 4292741104 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8880/statm: 649 295 249 194 0 35 0
[pid=8901] ppid=8880 vsize=75764 CPUtime=7.74
/proc/8901/stat : 8901 (aptitude) S 8880 8880 4159 34819 4229 4202496 16953 651 167 0 766 8 0 0 15 0 2 0 878792276 77582336 13032 1283457024 134512640 137933492 4293754208 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/8901/statm: 18941 13032 4029 836 0 13350 0
[pid=8901/tid=8903] ppid=8880 vsize=75764 CPUtime=6.15
/proc/8901/task/8903/stat : 8903 (aptitude) R 8880 8880 4159 34819 4229 4202560 7381 651 0 0 612 3 0 0 25 0 2 0 878792421 77582336 13032 1283457024 134512640 137933492 4293754208 18446744073709551615 136299502 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 11.07
Current children cumulated vsize (KiB) 78360

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

[startup+12.8121 s]
/proc/loadavg: 0.99 0.98 0.99 2/43 8905
/proc/meminfo: memFree=700288/1048576 swapFree=2080288/2097144
[pid=8880] ppid=8879 vsize=2596 CPUtime=3.33
/proc/8880/stat : 8880 (aptitude-trendy) S 8879 8880 4159 34819 4229 4202496 698 17464 0 4 1 0 320 12 18 0 1 0 878791856 2658304 295 1283457024 134512640 135304128 4292741104 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8880/statm: 649 295 249 194 0 35 0
[pid=8901] ppid=8880 vsize=75896 CPUtime=7.84
/proc/8901/stat : 8901 (aptitude) S 8880 8880 4159 34819 4229 4202496 17006 651 167 0 776 8 0 0 15 0 2 0 878792276 77717504 13085 1283457024 134512640 137933492 4293754208 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/8901/statm: 18974 13085 4029 836 0 13383 0
[pid=8901/tid=8903] ppid=8880 vsize=75896 CPUtime=6.25
/proc/8901/task/8903/stat : 8903 (aptitude) R 8880 8880 4159 34819 4229 4202560 7434 651 0 0 622 3 0 0 25 0 2 0 878792421 77717504 13085 1283457024 134512640 137933492 4293754208 18446744073709551615 136247328 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 11.17
Current children cumulated vsize (KiB) 78492

[startup+16.0028 s]
/proc/loadavg: 0.99 0.98 0.99 2/43 8905
/proc/meminfo: memFree=692600/1048576 swapFree=2080288/2097144
[pid=8880] ppid=8879 vsize=2596 CPUtime=3.33
/proc/8880/stat : 8880 (aptitude-trendy) S 8879 8880 4159 34819 4229 4202496 698 17464 0 4 1 0 320 12 18 0 1 0 878791856 2658304 295 1283457024 134512640 135304128 4292741104 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8880/statm: 649 295 249 194 0 35 0
[pid=8901] ppid=8880 vsize=83424 CPUtime=11.03
/proc/8901/stat : 8901 (aptitude) S 8880 8880 4159 34819 4229 4202496 18868 651 167 0 1095 8 0 0 15 0 2 0 878792276 85426176 14947 1283457024 134512640 137933492 4293754208 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/8901/statm: 20856 14947 4029 836 0 15265 0
[pid=8901/tid=8903] ppid=8880 vsize=83424 CPUtime=9.44
/proc/8901/task/8903/stat : 8903 (aptitude) R 8880 8880 4159 34819 4229 4202560 9296 651 0 0 941 3 0 0 25 0 2 0 878792421 85426176 14947 1283457024 134512640 137933492 4293754208 18446744073709551615 4153683051 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 14.36
Current children cumulated vsize (KiB) 86020

[startup+17.6068 s]
/proc/loadavg: 0.99 0.98 0.99 2/43 8906
/proc/meminfo: memFree=685872/1048576 swapFree=2080288/2097144
[pid=8880] ppid=8879 vsize=2596 CPUtime=3.33
/proc/8880/stat : 8880 (aptitude-trendy) S 8879 8880 4159 34819 4229 4202496 698 17464 0 4 1 0 320 12 18 0 1 0 878791856 2658304 295 1283457024 134512640 135304128 4292741104 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8880/statm: 649 295 249 194 0 35 0
[pid=8901] ppid=8880 vsize=86964 CPUtime=12.44
/proc/8901/stat : 8901 (aptitude) R 8880 8880 4159 34819 4229 4202496 21001 1061 184 0 1234 9 1 0 17 0 2 0 878792276 89051136 16030 1283457024 134512640 137933492 4293754208 18446744073709551615 4159801985 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/8901/statm: 21741 16030 4092 836 0 16143 0
[pid=8901/tid=8903] ppid=8880 vsize=86964 CPUtime=10.34
/proc/8901/task/8903/stat : 8903 (aptitude) S 8880 8880 4159 34819 4229 4202560 9974 1061 1 0 1030 3 1 0 23 0 2 0 878792421 89051136 16030 1283457024 134512640 137933492 4293754208 18446744073709551615 4294960130 0 134217728 4096 0 18446612132549436544 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 15.77
Current children cumulated vsize (KiB) 89560

[startup+18.4125 s]
/proc/loadavg: 0.99 0.98 0.99 2/43 8906
/proc/meminfo: memFree=685872/1048576 swapFree=2080288/2097144
[pid=8880] ppid=8879 vsize=2596 CPUtime=15.99
/proc/8880/stat : 8880 (aptitude-trendy) S 8879 8880 4159 34819 4229 4202496 725 39671 0 196 1 0 1575 23 18 0 1 0 878791856 2658304 295 1283457024 134512640 135304128 4292741104 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8880/statm: 649 295 249 194 0 35 0
Current children cumulated CPU time (s) 15.99
Current children cumulated vsize (KiB) 2596

[startup+18.8126 s]
/proc/loadavg: 0.99 0.98 0.99 2/42 8907
/proc/meminfo: memFree=716052/1048576 swapFree=2080288/2097144
[pid=8880] ppid=8879 vsize=2596 CPUtime=15.99
/proc/8880/stat : 8880 (aptitude-trendy) S 8879 8880 4159 34819 4229 4202496 725 39671 0 196 1 0 1575 23 18 0 1 0 878791856 2658304 295 1283457024 134512640 135304128 4292741104 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8880/statm: 649 295 249 194 0 35 0
[pid=8907] ppid=8880 vsize=21488 CPUtime=0.88
/proc/8907/stat : 8907 (aptsolutions.na) R 8880 8880 4159 34819 4229 4202496 4978 0 9 0 87 1 0 0 20 0 1 0 878793643 22003712 4875 1283457024 134512640 134971616 4292556320 18446744073709551615 134953676 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/8907/statm: 5372 4875 204 113 0 4774 0
Current children cumulated CPU time (s) 16.87
Current children cumulated vsize (KiB) 24084

[startup+19.2127 s]
/proc/loadavg: 0.99 0.98 0.99 2/42 8907
/proc/meminfo: memFree=716052/1048576 swapFree=2080288/2097144
[pid=8880] ppid=8879 vsize=2596 CPUtime=15.99
/proc/8880/stat : 8880 (aptitude-trendy) S 8879 8880 4159 34819 4229 4202496 725 39671 0 196 1 0 1575 23 18 0 1 0 878791856 2658304 295 1283457024 134512640 135304128 4292741104 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8880/statm: 649 295 249 194 0 35 0
[pid=8907] ppid=8880 vsize=29424 CPUtime=1.28
/proc/8907/stat : 8907 (aptsolutions.na) R 8880 8880 4159 34819 4229 4202496 6959 0 9 0 127 1 0 0 21 0 1 0 878793643 30130176 6856 1283457024 134512640 134971616 4292556320 18446744073709551615 134919410 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/8907/statm: 7356 6856 204 113 0 6758 0
Current children cumulated CPU time (s) 17.27
Current children cumulated vsize (KiB) 32020

[startup+19.3027 s]
/proc/loadavg: 0.99 0.98 0.99 2/42 8907
/proc/meminfo: memFree=716052/1048576 swapFree=2080288/2097144
[pid=8880] ppid=8879 vsize=2596 CPUtime=15.99
/proc/8880/stat : 8880 (aptitude-trendy) S 8879 8880 4159 34819 4229 4202496 725 39671 0 196 1 0 1575 23 18 0 1 0 878791856 2658304 295 1283457024 134512640 135304128 4292741104 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8880/statm: 649 295 249 194 0 35 0
[pid=8907] ppid=8880 vsize=32152 CPUtime=1.37
/proc/8907/stat : 8907 (aptsolutions.na) R 8880 8880 4159 34819 4229 4202496 7607 0 9 0 136 1 0 0 21 0 1 0 878793643 32923648 7504 1283457024 134512640 134971616 4292556320 18446744073709551615 134922010 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/8907/statm: 8038 7504 208 113 0 7440 0
Current children cumulated CPU time (s) 17.36
Current children cumulated vsize (KiB) 34748

Child status: 0
Real time (s): 19.3564
CPU time (s): 17.4331
CPU user time (s): 17.1771
CPU system time (s): 0.256016
CPU usage (%): 90.0635
Max. virtual memory (cumulated for all children) (KiB): 111008

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 17.1771
system time used= 0.256016
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 48596
page faults= 205
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 317
involuntary context switches= 363

runsolver used 0 second user time and 0.008 second system time

The end