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/rand108.sarge-etch.cudf.sarge-etch.log.runsolver ./aptitude-trendy-1.0 /home/misc2010/data/icse/sarge-etch/rand108.sarge-etch.cudf /home/misc2010/tmp/201012070034/aptitude-trendy-1.0/rand108.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: 1.13 1.08 1.03 5/44 6302
/proc/meminfo: memFree=762900/1048576 swapFree=2077656/2097144
[pid=6301] ppid=6300 vsize=2576 CPUtime=0
/proc/6301/stat : 6301 (aptitude-trendy) R 6300 6301 4159 34819 4229 4202496 359 0 0 0 0 0 0 0 25 0 1 0 878036555 2637824 273 1283457024 134512640 135304128 4292077392 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/6301/statm: 644 273 232 194 0 30 0
[pid=6302] ppid=6301 vsize=2576 CPUtime=0
/proc/6302/stat : 6302 (aptitude-trendy) R 6301 6301 4159 34819 4229 4202560 0 0 0 0 0 0 0 0 25 0 1 0 878036555 2637824 41 1283457024 134512640 135304128 4292077392 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/6302/statm: 644 41 0 194 0 30 0

[startup+0.127814 s]
/proc/loadavg: 1.13 1.08 1.03 5/44 6302
/proc/meminfo: memFree=762900/1048576 swapFree=2077656/2097144
[pid=6301] ppid=6300 vsize=2588 CPUtime=0.03
/proc/6301/stat : 6301 (aptitude-trendy) R 6300 6301 4159 34819 4229 4202496 548 1857 0 0 0 1 0 2 25 0 1 0 878036555 2650112 284 1283457024 134512640 135304128 4292077392 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/6301/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2588

[startup+0.207827 s]
/proc/loadavg: 1.13 1.08 1.03 5/44 6302
/proc/meminfo: memFree=762900/1048576 swapFree=2077656/2097144
[pid=6301] ppid=6300 vsize=2588 CPUtime=0.03
/proc/6301/stat : 6301 (aptitude-trendy) S 6300 6301 4159 34819 4229 4202496 566 1857 0 0 0 1 0 2 25 0 1 0 878036555 2650112 284 1283457024 134512640 135304128 4292077392 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6301/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2588

[startup+0.307847 s]
/proc/loadavg: 1.13 1.08 1.03 5/44 6302
/proc/meminfo: memFree=762900/1048576 swapFree=2077656/2097144
[pid=6301] ppid=6300 vsize=2588 CPUtime=0.03
/proc/6301/stat : 6301 (aptitude-trendy) S 6300 6301 4159 34819 4229 4202496 566 1857 0 0 0 1 0 2 25 0 1 0 878036555 2650112 284 1283457024 134512640 135304128 4292077392 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6301/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2588

[startup+0.707912 s]
/proc/loadavg: 1.13 1.08 1.03 5/44 6302
/proc/meminfo: memFree=762900/1048576 swapFree=2077656/2097144
[pid=6301] ppid=6300 vsize=2588 CPUtime=0.03
/proc/6301/stat : 6301 (aptitude-trendy) S 6300 6301 4159 34819 4229 4202496 566 1857 0 0 0 1 0 2 25 0 1 0 878036555 2650112 284 1283457024 134512640 135304128 4292077392 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6301/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2588

[startup+1.50805 s]
/proc/loadavg: 1.13 1.08 1.03 2/45 6312
/proc/meminfo: memFree=733632/1048576 swapFree=2077656/2097144
[pid=6301] ppid=6300 vsize=2588 CPUtime=0.03
/proc/6301/stat : 6301 (aptitude-trendy) S 6300 6301 4159 34819 4229 4202496 566 1857 0 0 0 1 0 2 25 0 1 0 878036555 2650112 284 1283457024 134512640 135304128 4292077392 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6301/statm: 647 284 240 194 0 33 0
[pid=6312] ppid=6301 vsize=33936 CPUtime=1.47
/proc/6312/stat : 6312 (cudftodeb.nativ) R 6301 6301 4159 34819 4229 4202496 8083 0 0 0 145 2 0 0 25 0 1 0 878036558 34750464 8010 1283457024 134512640 135004320 4291045040 18446744073709551615 134996501 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/6312/statm: 8484 8010 236 121 0 7876 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 36524

[startup+3.10858 s]
/proc/loadavg: 1.13 1.08 1.03 2/45 6312
/proc/meminfo: memFree=708460/1048576 swapFree=2077656/2097144
[pid=6301] ppid=6300 vsize=2588 CPUtime=0.03
/proc/6301/stat : 6301 (aptitude-trendy) S 6300 6301 4159 34819 4229 4202496 566 1857 0 0 0 1 0 2 25 0 1 0 878036555 2650112 284 1283457024 134512640 135304128 4292077392 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6301/statm: 647 284 240 194 0 33 0
[pid=6312] ppid=6301 vsize=30248 CPUtime=3.06
/proc/6312/stat : 6312 (cudftodeb.nativ) R 6301 6301 4159 34819 4229 4202496 12435 0 0 0 300 6 0 0 25 0 1 0 878036558 30973952 7116 1283457024 134512640 135004320 4291045040 18446744073709551615 134863550 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/6312/statm: 7562 7116 237 121 0 6954 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 32836

[startup+6.31335 s]
/proc/loadavg: 1.12 1.08 1.03 2/45 6323
/proc/meminfo: memFree=707312/1048576 swapFree=2077656/2097144
[pid=6301] ppid=6300 vsize=2596 CPUtime=3.33
/proc/6301/stat : 6301 (aptitude-trendy) S 6300 6301 4159 34819 4229 4202496 697 17463 0 1 0 1 320 12 18 0 1 0 878036555 2658304 295 1283457024 134512640 135304128 4292077392 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6301/statm: 649 295 249 194 0 35 0
[pid=6322] ppid=6301 vsize=46884 CPUtime=1.39
/proc/6322/stat : 6322 (aptitude) R 6301 6301 4159 34819 4229 4202496 9602 650 167 0 136 3 0 0 20 0 2 0 878036984 48009216 6027 1283457024 134512640 137933492 4288516208 18446744073709551615 4153629982 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/6322/statm: 11721 6027 3975 836 0 6130 0
Current children cumulated CPU time (s) 4.72
Current children cumulated vsize (KiB) 49480
heavy processes:

[startup+12.7048 s]
/proc/loadavg: 1.27 1.11 1.04 2/46 6326
/proc/meminfo: memFree=678288/1048576 swapFree=2077656/2097144
[pid=6301] ppid=6300 vsize=2596 CPUtime=3.33
/proc/6301/stat : 6301 (aptitude-trendy) S 6300 6301 4159 34819 4229 4202496 697 17463 0 1 0 1 320 12 18 0 1 0 878036555 2658304 295 1283457024 134512640 135304128 4292077392 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6301/statm: 649 295 249 194 0 35 0
[pid=6322] ppid=6301 vsize=75896 CPUtime=7.78
/proc/6322/stat : 6322 (aptitude) S 6301 6301 4159 34819 4229 4202496 17025 650 167 0 772 6 0 0 15 0 2 0 878036984 77717504 13065 1283457024 134512640 137933492 4288516208 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/6322/statm: 18974 13065 4028 836 0 13383 0
[pid=6322/tid=6324] ppid=6301 vsize=75896 CPUtime=6.18
/proc/6322/task/6324/stat : 6324 (aptitude) R 6301 6301 4159 34819 4229 4202560 7419 650 0 0 615 3 0 0 25 0 2 0 878037119 77717504 13065 1283457024 134512640 137933492 4288516208 18446744073709551615 4155561696 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 11.11
Current children cumulated vsize (KiB) 78492

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

[startup+12.8049 s]
/proc/loadavg: 1.27 1.11 1.04 2/46 6326
/proc/meminfo: memFree=678288/1048576 swapFree=2077656/2097144
[pid=6301] ppid=6300 vsize=2596 CPUtime=3.33
/proc/6301/stat : 6301 (aptitude-trendy) S 6300 6301 4159 34819 4229 4202496 697 17463 0 1 0 1 320 12 18 0 1 0 878036555 2658304 295 1283457024 134512640 135304128 4292077392 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6301/statm: 649 295 249 194 0 35 0
[pid=6322] ppid=6301 vsize=76028 CPUtime=7.88
/proc/6322/stat : 6322 (aptitude) S 6301 6301 4159 34819 4229 4202496 17083 650 167 0 782 6 0 0 15 0 2 0 878036984 77852672 13123 1283457024 134512640 137933492 4288516208 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/6322/statm: 19007 13123 4028 836 0 13416 0
[pid=6322/tid=6324] ppid=6301 vsize=76028 CPUtime=6.28
/proc/6322/task/6324/stat : 6324 (aptitude) R 6301 6301 4159 34819 4229 4202560 7477 650 0 0 625 3 0 0 25 0 2 0 878037119 77852672 13123 1283457024 134512640 137933492 4288516208 18446744073709551615 4153630020 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 11.21
Current children cumulated vsize (KiB) 78624

[startup+19.2068 s]
/proc/loadavg: 1.23 1.11 1.04 2/46 6326
/proc/meminfo: memFree=658324/1048576 swapFree=2077656/2097144
[pid=6301] ppid=6300 vsize=2596 CPUtime=3.33
/proc/6301/stat : 6301 (aptitude-trendy) S 6300 6301 4159 34819 4229 4202496 697 17463 0 1 0 1 320 12 18 0 1 0 878036555 2658304 295 1283457024 134512640 135304128 4292077392 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6301/statm: 649 295 249 194 0 35 0
[pid=6322] ppid=6301 vsize=94640 CPUtime=14.27
/proc/6322/stat : 6322 (aptitude) S 6301 6301 4159 34819 4229 4202496 21728 650 167 0 1417 10 0 0 15 0 2 0 878036984 96911360 17768 1283457024 134512640 137933492 4288516208 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/6322/statm: 23660 17768 4028 836 0 18069 0
[pid=6322/tid=6324] ppid=6301 vsize=94640 CPUtime=12.67
/proc/6322/task/6324/stat : 6324 (aptitude) R 6301 6301 4159 34819 4229 4202560 12122 650 0 0 1260 7 0 0 25 0 2 0 878037119 96911360 17768 1283457024 134512640 137933492 4288516208 18446744073709551615 136328811 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 17.6
Current children cumulated vsize (KiB) 97236

[startup+22.4077 s]
/proc/loadavg: 1.23 1.11 1.04 2/46 6326
/proc/meminfo: memFree=650264/1048576 swapFree=2077656/2097144
[pid=6301] ppid=6300 vsize=2596 CPUtime=3.33
/proc/6301/stat : 6301 (aptitude-trendy) S 6300 6301 4159 34819 4229 4202496 697 17463 0 1 0 1 320 12 18 0 1 0 878036555 2658304 295 1283457024 134512640 135304128 4292077392 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6301/statm: 649 295 249 194 0 35 0
[pid=6322] ppid=6301 vsize=102824 CPUtime=17.47
/proc/6322/stat : 6322 (aptitude) S 6301 6301 4159 34819 4229 4202496 23779 650 167 0 1737 10 0 0 15 0 2 0 878036984 105291776 19819 1283457024 134512640 137933492 4288516208 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/6322/statm: 25706 19819 4033 836 0 20115 0
[pid=6322/tid=6324] ppid=6301 vsize=102824 CPUtime=15.87
/proc/6322/task/6324/stat : 6324 (aptitude) R 6301 6301 4159 34819 4229 4202560 14173 650 0 0 1580 7 0 0 25 0 2 0 878037119 105291776 19819 1283457024 134512640 137933492 4288516208 18446744073709551615 136299458 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 20.8
Current children cumulated vsize (KiB) 105420

[startup+24.0053 s]
/proc/loadavg: 1.23 1.11 1.04 3/46 6326
/proc/meminfo: memFree=646980/1048576 swapFree=2077656/2097144
[pid=6301] ppid=6300 vsize=2596 CPUtime=22.35
/proc/6301/stat : 6301 (aptitude-trendy) S 6300 6301 4159 34819 4229 4202496 724 44204 0 170 1 1 2206 27 18 0 1 0 878036555 2658304 295 1283457024 134512640 135304128 4292077392 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6301/statm: 649 295 249 194 0 35 0
Current children cumulated CPU time (s) 22.35
Current children cumulated vsize (KiB) 2596

[startup+24.8082 s]
/proc/loadavg: 1.29 1.12 1.05 2/45 6328
/proc/meminfo: memFree=706716/1048576 swapFree=2077656/2097144
[pid=6301] ppid=6300 vsize=2596 CPUtime=22.35
/proc/6301/stat : 6301 (aptitude-trendy) S 6300 6301 4159 34819 4229 4202496 724 44204 0 170 1 1 2206 27 18 0 1 0 878036555 2658304 295 1283457024 134512640 135304128 4292077392 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6301/statm: 649 295 249 194 0 35 0
[pid=6328] ppid=6301 vsize=18756 CPUtime=0.79
/proc/6328/stat : 6328 (aptsolutions.na) R 6301 6301 4159 34819 4229 4202496 4343 0 9 0 73 6 0 0 20 0 1 0 878038951 19206144 4239 1283457024 134512640 134971616 4287892800 18446744073709551615 134954131 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/6328/statm: 4689 4239 204 113 0 4091 0
Current children cumulated CPU time (s) 23.14
Current children cumulated vsize (KiB) 21352

[startup+25.2084 s]
/proc/loadavg: 1.29 1.12 1.05 2/45 6328
/proc/meminfo: memFree=706716/1048576 swapFree=2077656/2097144
[pid=6301] ppid=6300 vsize=2596 CPUtime=22.35
/proc/6301/stat : 6301 (aptitude-trendy) S 6300 6301 4159 34819 4229 4202496 724 44204 0 170 1 1 2206 27 18 0 1 0 878036555 2658304 295 1283457024 134512640 135304128 4292077392 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6301/statm: 649 295 249 194 0 35 0
[pid=6328] ppid=6301 vsize=26940 CPUtime=1.19
/proc/6328/stat : 6328 (aptsolutions.na) R 6301 6301 4159 34819 4229 4202496 6347 0 9 0 113 6 0 0 21 0 1 0 878038951 27586560 6243 1283457024 134512640 134971616 4287892800 18446744073709551615 134954176 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/6328/statm: 6735 6243 204 113 0 6137 0
Current children cumulated CPU time (s) 23.54
Current children cumulated vsize (KiB) 29536

[startup+25.4084 s]
/proc/loadavg: 1.29 1.12 1.05 2/45 6328
/proc/meminfo: memFree=685016/1048576 swapFree=2077656/2097144
[pid=6301] ppid=6300 vsize=2596 CPUtime=22.35
/proc/6301/stat : 6301 (aptitude-trendy) S 6300 6301 4159 34819 4229 4202496 724 44204 0 170 1 1 2206 27 18 0 1 0 878036555 2658304 295 1283457024 134512640 135304128 4292077392 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6301/statm: 649 295 249 194 0 35 0
[pid=6328] ppid=6301 vsize=31900 CPUtime=1.39
/proc/6328/stat : 6328 (aptsolutions.na) R 6301 6301 4159 34819 4229 4202496 7561 0 9 0 132 7 0 0 22 0 1 0 878038951 32665600 7457 1283457024 134512640 134971616 4287892800 18446744073709551615 4158511107 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/6328/statm: 7975 7457 208 113 0 7377 0
Current children cumulated CPU time (s) 23.74
Current children cumulated vsize (KiB) 34496

Child status: 0
Real time (s): 25.47
CPU time (s): 23.8215
CPU user time (s): 23.4535
CPU system time (s): 0.368023
CPU usage (%): 93.5278
Max. virtual memory (cumulated for all children) (KiB): 111004

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 23.4535
system time used= 0.368023
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 53180
page faults= 179
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 287
involuntary context switches= 439

runsolver used 0 second user time and 0 second system time

The end