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/201012061533/aptitude-paranoid-1.0/randba6b5b.cudf.easy.log.runsolver ./aptitude-paranoid-1.0 /home/misc2010/data/2010/easy//randba6b5b.cudf /home/misc2010/tmp/201012061533/aptitude-paranoid-1.0/randba6b5b.cudf.easy.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.50 1.25 1.23 4/46 660
/proc/meminfo: memFree=803988/1048576 swapFree=2078696/2097144
[pid=650] ppid=649 vsize=2580 CPUtime=0.02
/proc/650/stat : 650 (aptitude-parano) S 649 650 2059 34821 2220 4202496 566 1856 0 0 0 0 0 2 25 0 1 0 876690697 2641920 283 1283457024 134512640 135304128 4294584768 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/650/statm: 645 283 240 194 0 31 0
[pid=660] ppid=650 vsize=3268 CPUtime=0.02
/proc/660/stat : 660 (cudftodeb.nativ) R 650 650 2059 34821 2220 4202496 507 0 0 0 2 0 0 0 25 0 1 0 876690700 3346432 434 1283457024 134512640 135004320 4293232832 18446744073709551615 134986374 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/660/statm: 817 434 224 121 0 209 0

[startup+0.243707 s]
/proc/loadavg: 1.50 1.25 1.23 4/46 660
/proc/meminfo: memFree=803988/1048576 swapFree=2078696/2097144
[pid=650] ppid=649 vsize=2580 CPUtime=0.02
/proc/650/stat : 650 (aptitude-parano) S 649 650 2059 34821 2220 4202496 566 1856 0 0 0 0 0 2 25 0 1 0 876690697 2641920 283 1283457024 134512640 135304128 4294584768 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/650/statm: 645 283 240 194 0 31 0
[pid=660] ppid=650 vsize=7484 CPUtime=0.22
/proc/660/stat : 660 (cudftodeb.nativ) R 650 650 2059 34821 2220 4202496 1560 0 0 0 22 0 0 0 25 0 1 0 876690700 7663616 1487 1283457024 134512640 135004320 4293232832 18446744073709551615 134828030 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/660/statm: 1871 1487 225 121 0 1263 0
Current children cumulated CPU time (s) 0.24
Current children cumulated vsize (KiB) 10064

[startup+0.313718 s]
/proc/loadavg: 1.50 1.25 1.23 4/46 660
/proc/meminfo: memFree=803988/1048576 swapFree=2078696/2097144
[pid=650] ppid=649 vsize=2580 CPUtime=0.02
/proc/650/stat : 650 (aptitude-parano) S 649 650 2059 34821 2220 4202496 566 1856 0 0 0 0 0 2 25 0 1 0 876690697 2641920 283 1283457024 134512640 135304128 4294584768 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/650/statm: 645 283 240 194 0 31 0
[pid=660] ppid=650 vsize=8972 CPUtime=0.28
/proc/660/stat : 660 (cudftodeb.nativ) R 650 650 2059 34821 2220 4202496 1925 0 0 0 28 0 0 0 25 0 1 0 876690700 9187328 1852 1283457024 134512640 135004320 4293232832 18446744073709551615 134946534 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/660/statm: 2243 1852 225 121 0 1635 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 11552

[startup+0.413737 s]
/proc/loadavg: 1.50 1.25 1.23 4/46 660
/proc/meminfo: memFree=803988/1048576 swapFree=2078696/2097144
[pid=650] ppid=649 vsize=2580 CPUtime=0.02
/proc/650/stat : 650 (aptitude-parano) S 649 650 2059 34821 2220 4202496 566 1856 0 0 0 0 0 2 25 0 1 0 876690697 2641920 283 1283457024 134512640 135304128 4294584768 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/650/statm: 645 283 240 194 0 31 0
[pid=660] ppid=650 vsize=11204 CPUtime=0.38
/proc/660/stat : 660 (cudftodeb.nativ) R 650 650 2059 34821 2220 4202496 2458 0 0 0 38 0 0 0 25 0 1 0 876690700 11472896 2385 1283457024 134512640 135004320 4293232832 18446744073709551615 134607542 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/660/statm: 2801 2385 225 121 0 2193 0
Current children cumulated CPU time (s) 0.4
Current children cumulated vsize (KiB) 13784

[startup+0.713776 s]
/proc/loadavg: 1.50 1.25 1.23 4/46 660
/proc/meminfo: memFree=803988/1048576 swapFree=2078696/2097144
[pid=650] ppid=649 vsize=2580 CPUtime=0.02
/proc/650/stat : 650 (aptitude-parano) S 649 650 2059 34821 2220 4202496 566 1856 0 0 0 0 0 2 25 0 1 0 876690697 2641920 283 1283457024 134512640 135304128 4294584768 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/650/statm: 645 283 240 194 0 31 0
[pid=660] ppid=650 vsize=18060 CPUtime=0.68
/proc/660/stat : 660 (cudftodeb.nativ) R 650 650 2059 34821 2220 4202496 4120 0 0 0 68 0 0 0 25 0 1 0 876690700 18493440 4047 1283457024 134512640 135004320 4293232832 18446744073709551615 134625353 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/660/statm: 4515 4047 225 121 0 3907 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 20640

[startup+1.51396 s]
/proc/loadavg: 1.46 1.25 1.23 2/47 661
/proc/meminfo: memFree=779144/1048576 swapFree=2078696/2097144
[pid=650] ppid=649 vsize=2580 CPUtime=0.02
/proc/650/stat : 650 (aptitude-parano) S 649 650 2059 34821 2220 4202496 566 1856 0 0 0 0 0 2 25 0 1 0 876690697 2641920 283 1283457024 134512640 135304128 4294584768 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/650/statm: 645 283 240 194 0 31 0
[pid=660] ppid=650 vsize=34924 CPUtime=1.48
/proc/660/stat : 660 (cudftodeb.nativ) R 650 650 2059 34821 2220 4202496 8294 0 0 0 144 4 0 0 25 0 1 0 876690700 35762176 8221 1283457024 134512640 135004320 4293232832 18446744073709551615 134948176 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/660/statm: 8731 8221 225 121 0 8123 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 37504

[startup+3.1144 s]
/proc/loadavg: 1.46 1.25 1.23 3/47 661
/proc/meminfo: memFree=754468/1048576 swapFree=2078696/2097144
[pid=650] ppid=649 vsize=2580 CPUtime=0.02
/proc/650/stat : 650 (aptitude-parano) S 649 650 2059 34821 2220 4202496 566 1856 0 0 0 0 0 2 25 0 1 0 876690697 2641920 283 1283457024 134512640 135304128 4294584768 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/650/statm: 645 283 240 194 0 31 0
[pid=660] ppid=650 vsize=31476 CPUtime=3.07
/proc/660/stat : 660 (cudftodeb.nativ) R 650 650 2059 34821 2220 4202496 12311 0 0 0 299 8 0 0 25 0 1 0 876690700 32231424 7419 1283457024 134512640 135004320 4293232832 18446744073709551615 134813018 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/660/statm: 7869 7419 237 121 0 7261 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 34056

[startup+6.30211 s]
/proc/loadavg: 1.46 1.25 1.23 2/47 673
/proc/meminfo: memFree=756568/1048576 swapFree=2078696/2097144
[pid=650] ppid=649 vsize=2588 CPUtime=3.49
/proc/650/stat : 650 (aptitude-parano) S 649 650 2059 34821 2220 4202496 696 18013 0 1 0 0 334 15 15 0 1 0 876690697 2650112 294 1283457024 134512640 135304128 4294584768 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/650/statm: 647 294 249 194 0 33 0
[pid=672] ppid=650 vsize=49828 CPUtime=1.29
/proc/672/stat : 672 (aptitude) R 650 650 2059 34821 2220 4202496 10246 241 177 0 118 11 0 0 19 0 2 0 876691123 51023872 6718 1283457024 134512640 137933492 4287893408 18446744073709551615 4153158992 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/672/statm: 12457 6718 4129 836 0 6673 0
Current children cumulated CPU time (s) 4.78
Current children cumulated vsize (KiB) 52416
heavy processes:

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

[startup+6.50209 s]
/proc/loadavg: 1.42 1.24 1.23 2/48 675
/proc/meminfo: memFree=748252/1048576 swapFree=2078696/2097144
[pid=650] ppid=649 vsize=2588 CPUtime=3.49
/proc/650/stat : 650 (aptitude-parano) S 649 650 2059 34821 2220 4202496 696 18013 0 1 0 0 334 15 15 0 1 0 876690697 2650112 294 1283457024 134512640 135304128 4294584768 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/650/statm: 647 294 249 194 0 33 0
[pid=672] ppid=650 vsize=49884 CPUtime=1.48
/proc/672/stat : 672 (aptitude) R 650 650 2059 34821 2220 4202496 10638 650 177 0 137 11 0 0 20 0 2 0 876691123 51081216 6753 1283457024 134512640 137933492 4287893408 18446744073709551615 4153158896 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/672/statm: 12471 6753 4165 836 0 6687 0
[pid=672/tid=674] ppid=650 vsize=49884 CPUtime=0
/proc/672/task/674/stat : 674 (aptitude) S 650 650 2059 34821 2220 4202560 5 650 0 0 0 0 0 0 15 0 2 0 876691290 51081216 6753 1283457024 134512640 137933492 4287893408 18446744073709551615 4294960130 0 134217728 4096 0 18446612133359098816 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 4.97
Current children cumulated vsize (KiB) 52472

[startup+8.10243 s]
/proc/loadavg: 1.42 1.24 1.23 2/47 678
/proc/meminfo: memFree=741936/1048576 swapFree=2078696/2097144
[pid=650] ppid=649 vsize=2588 CPUtime=5.52
/proc/650/stat : 650 (aptitude-parano) S 649 650 2059 34821 2220 4202496 723 31649 0 178 0 0 522 30 18 0 1 0 876690697 2650112 294 1283457024 134512640 135304128 4294584768 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/650/statm: 647 294 249 194 0 33 0
[pid=678] ppid=650 vsize=25456 CPUtime=1.05
/proc/678/stat : 678 (aptsolutions.na) R 650 650 2059 34821 2220 4202496 5981 0 0 0 103 2 0 0 23 0 1 0 876691402 26066944 5868 1283457024 134512640 134971616 4293732640 18446744073709551615 134915739 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/678/statm: 6364 5868 204 113 0 5766 0
Current children cumulated CPU time (s) 6.57
Current children cumulated vsize (KiB) 28044

[startup+8.50254 s]
/proc/loadavg: 1.42 1.24 1.23 2/47 678
/proc/meminfo: memFree=741936/1048576 swapFree=2078696/2097144
[pid=650] ppid=649 vsize=2588 CPUtime=5.52
/proc/650/stat : 650 (aptitude-parano) S 649 650 2059 34821 2220 4202496 723 31649 0 178 0 0 522 30 18 0 1 0 876690697 2650112 294 1283457024 134512640 135304128 4294584768 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/650/statm: 647 294 249 194 0 33 0
[pid=678] ppid=650 vsize=33888 CPUtime=1.45
/proc/678/stat : 678 (aptsolutions.na) R 650 650 2059 34821 2220 4202496 8029 0 0 0 142 3 0 0 25 0 1 0 876691402 34701312 7916 1283457024 134512640 134971616 4293732640 18446744073709551615 134945261 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/678/statm: 8472 7916 204 113 0 7874 0
Current children cumulated CPU time (s) 6.97
Current children cumulated vsize (KiB) 36476

[startup+8.70261 s]
/proc/loadavg: 1.42 1.24 1.23 2/47 678
/proc/meminfo: memFree=741936/1048576 swapFree=2078696/2097144
[pid=650] ppid=649 vsize=2588 CPUtime=5.52
/proc/650/stat : 650 (aptitude-parano) S 649 650 2059 34821 2220 4202496 723 31649 0 178 0 0 522 30 18 0 1 0 876690697 2650112 294 1283457024 134512640 135304128 4294584768 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/650/statm: 647 294 249 194 0 33 0
[pid=678] ppid=650 vsize=48616 CPUtime=1.65
/proc/678/stat : 678 (aptsolutions.na) R 650 650 2059 34821 2220 4202496 11069 0 0 0 161 4 0 0 25 0 1 0 876691402 49782784 10954 1283457024 134512640 134971616 4293732640 18446744073709551615 134912812 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/678/statm: 12154 10954 209 113 0 11556 0
Current children cumulated CPU time (s) 7.17
Current children cumulated vsize (KiB) 51204

Child status: 0
Real time (s): 8.71401
CPU time (s): 7.19245
CPU user time (s): 6.83243
CPU system time (s): 0.360022
CPU usage (%): 82.5389
Max. virtual memory (cumulated for all children) (KiB): 111004

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 6.83243
system time used= 0.360022
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 43749
page faults= 178
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 243
involuntary context switches= 276

runsolver used 0 second user time and 0 second system time

The end