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/rand14ba69.cudf.difficult.log.runsolver ./aptitude-paranoid-1.0 /home/misc2010/data/2010/difficult//rand14ba69.cudf /home/misc2010/tmp/201012061533/aptitude-paranoid-1.0/rand14ba69.cudf.difficult.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.58 1.20 1.09 5/45 7951
/proc/meminfo: memFree=781100/1048576 swapFree=2078760/2097144
[pid=7951] ppid=7950 vsize=820 CPUtime=0.01
/proc/7951/stat : 7951 (aptitude-parano) R 7950 7951 2059 34821 2220 4194304 74 0 0 0 0 1 0 0 25 0 1 0 874954459 839680 2 1283457024 0 0 4290261804 18446744073709551615 4294960130 0 0 0 0 0 0 0 17 0 0 0 0
/proc/7951/statm: 205 2 0 0 0 6 0

[startup+0.150456 s]
/proc/loadavg: 1.58 1.20 1.09 5/45 7951
/proc/meminfo: memFree=781100/1048576 swapFree=2078760/2097144
[pid=7951] ppid=7950 vsize=2588 CPUtime=0.03
/proc/7951/stat : 7951 (aptitude-parano) S 7950 7951 2059 34821 2220 4202496 567 1864 0 0 0 1 0 2 25 0 1 0 874954459 2650112 283 1283457024 134512640 135304128 4290253488 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7951/statm: 647 283 240 194 0 33 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2588

[startup+0.210476 s]
/proc/loadavg: 1.58 1.20 1.09 5/45 7951
/proc/meminfo: memFree=781100/1048576 swapFree=2078760/2097144
[pid=7951] ppid=7950 vsize=2588 CPUtime=0.03
/proc/7951/stat : 7951 (aptitude-parano) S 7950 7951 2059 34821 2220 4202496 567 1864 0 0 0 1 0 2 25 0 1 0 874954459 2650112 283 1283457024 134512640 135304128 4290253488 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7951/statm: 647 283 240 194 0 33 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2588

[startup+0.310513 s]
/proc/loadavg: 1.58 1.20 1.09 5/45 7951
/proc/meminfo: memFree=781100/1048576 swapFree=2078760/2097144
[pid=7951] ppid=7950 vsize=2588 CPUtime=0.03
/proc/7951/stat : 7951 (aptitude-parano) S 7950 7951 2059 34821 2220 4202496 567 1864 0 0 0 1 0 2 25 0 1 0 874954459 2650112 283 1283457024 134512640 135304128 4290253488 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7951/statm: 647 283 240 194 0 33 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2588

[startup+0.7106 s]
/proc/loadavg: 1.58 1.20 1.09 5/45 7951
/proc/meminfo: memFree=781100/1048576 swapFree=2078760/2097144
[pid=7951] ppid=7950 vsize=2588 CPUtime=0.03
/proc/7951/stat : 7951 (aptitude-parano) S 7950 7951 2059 34821 2220 4202496 567 1864 0 0 0 1 0 2 25 0 1 0 874954459 2650112 283 1283457024 134512640 135304128 4290253488 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7951/statm: 647 283 240 194 0 33 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2588

[startup+1.5108 s]
/proc/loadavg: 1.58 1.20 1.09 2/47 7962
/proc/meminfo: memFree=745132/1048576 swapFree=2078760/2097144
[pid=7951] ppid=7950 vsize=2588 CPUtime=0.03
/proc/7951/stat : 7951 (aptitude-parano) S 7950 7951 2059 34821 2220 4202496 567 1864 0 0 0 1 0 2 25 0 1 0 874954459 2650112 283 1283457024 134512640 135304128 4290253488 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7951/statm: 647 283 240 194 0 33 0
[pid=7962] ppid=7951 vsize=33996 CPUtime=1.47
/proc/7962/stat : 7962 (cudftodeb.nativ) R 7951 7951 2059 34821 2220 4202496 8083 0 0 0 144 3 0 0 25 0 1 0 874954463 34811904 8009 1283457024 134512640 135004320 4292116400 18446744073709551615 134996501 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/7962/statm: 8499 8009 225 121 0 7891 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 36584

[startup+3.11121 s]
/proc/loadavg: 1.58 1.20 1.09 2/47 7962
/proc/meminfo: memFree=722564/1048576 swapFree=2078760/2097144
[pid=7951] ppid=7950 vsize=2588 CPUtime=0.03
/proc/7951/stat : 7951 (aptitude-parano) S 7950 7951 2059 34821 2220 4202496 567 1864 0 0 0 1 0 2 25 0 1 0 874954459 2650112 283 1283457024 134512640 135304128 4290253488 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7951/statm: 647 283 240 194 0 33 0
[pid=7962] ppid=7951 vsize=69348 CPUtime=3.07
/proc/7962/stat : 7962 (cudftodeb.nativ) R 7951 7951 2059 34821 2220 4202496 16738 0 0 0 301 6 0 0 25 0 1 0 874954463 71012352 16664 1283457024 134512640 135004320 4292116400 18446744073709551615 134964935 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/7962/statm: 17337 16664 237 121 0 16729 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 71936

[startup+6.3048 s]
/proc/loadavg: 1.54 1.19 1.09 2/47 7962
/proc/meminfo: memFree=712024/1048576 swapFree=2078760/2097144
[pid=7951] ppid=7950 vsize=2596 CPUtime=5.57
/proc/7951/stat : 7951 (aptitude-parano) S 7950 7951 2059 34821 2220 4202496 647 25838 0 0 0 1 534 22 18 0 1 0 874954459 2658304 286 1283457024 134512640 135304128 4290253488 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7951/statm: 649 286 241 194 0 35 0
Current children cumulated CPU time (s) 5.57
Current children cumulated vsize (KiB) 2596

[startup+12.7111 s]
/proc/loadavg: 1.49 1.19 1.09 2/47 7978
/proc/meminfo: memFree=689536/1048576 swapFree=2078760/2097144
[pid=7951] ppid=7950 vsize=2596 CPUtime=10.35
/proc/7951/stat : 7951 (aptitude-parano) S 7950 7951 2059 34821 2220 4202496 721 47628 0 267 0 1 990 44 18 0 1 0 874954459 2658304 294 1283457024 134512640 135304128 4290253488 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7951/statm: 649 294 249 194 0 35 0
[pid=7978] ppid=7951 vsize=21560 CPUtime=0.87
/proc/7978/stat : 7978 (aptsolutions.na) R 7951 7951 2059 34821 2220 4202496 5041 0 0 0 84 3 0 0 25 0 1 0 874955644 22077440 4927 1283457024 134512640 134971616 4289238240 18446744073709551615 134919050 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/7978/statm: 5390 4927 204 113 0 4792 0
Current children cumulated CPU time (s) 11.22
Current children cumulated vsize (KiB) 24156

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

[startup+12.8111 s]
/proc/loadavg: 1.49 1.19 1.09 2/47 7978
/proc/meminfo: memFree=689536/1048576 swapFree=2078760/2097144
[pid=7951] ppid=7950 vsize=2596 CPUtime=10.35
/proc/7951/stat : 7951 (aptitude-parano) S 7950 7951 2059 34821 2220 4202496 721 47628 0 267 0 1 990 44 18 0 1 0 874954459 2658304 294 1283457024 134512640 135304128 4290253488 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7951/statm: 649 294 249 194 0 35 0
[pid=7978] ppid=7951 vsize=24040 CPUtime=0.97
/proc/7978/stat : 7978 (aptsolutions.na) R 7951 7951 2059 34821 2220 4202496 5610 0 0 0 94 3 0 0 25 0 1 0 874955644 24616960 5496 1283457024 134512640 134971616 4289238240 18446744073709551615 134915798 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/7978/statm: 6010 5496 204 113 0 5412 0
Current children cumulated CPU time (s) 11.32
Current children cumulated vsize (KiB) 26636

[startup+13.6113 s]
/proc/loadavg: 1.45 1.19 1.09 2/47 7978
/proc/meminfo: memFree=666224/1048576 swapFree=2078760/2097144
[pid=7951] ppid=7950 vsize=2596 CPUtime=10.35
/proc/7951/stat : 7951 (aptitude-parano) S 7950 7951 2059 34821 2220 4202496 721 47628 0 267 0 1 990 44 18 0 1 0 874954459 2658304 294 1283457024 134512640 135304128 4290253488 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7951/statm: 649 294 249 194 0 35 0
[pid=7978] ppid=7951 vsize=40288 CPUtime=1.76
/proc/7978/stat : 7978 (aptsolutions.na) R 7951 7951 2059 34821 2220 4202496 9590 0 0 0 170 6 0 0 25 0 1 0 874955644 41254912 9476 1283457024 134512640 134971616 4289238240 18446744073709551615 134953966 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/7978/statm: 10072 9476 204 113 0 9474 0
Current children cumulated CPU time (s) 12.11
Current children cumulated vsize (KiB) 42884

[startup+14.0114 s]
/proc/loadavg: 1.45 1.19 1.09 2/47 7978
/proc/meminfo: memFree=666224/1048576 swapFree=2078760/2097144
[pid=7951] ppid=7950 vsize=2596 CPUtime=10.35
/proc/7951/stat : 7951 (aptitude-parano) S 7950 7951 2059 34821 2220 4202496 721 47628 0 267 0 1 990 44 18 0 1 0 874954459 2658304 294 1283457024 134512640 135304128 4290253488 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7951/statm: 649 294 249 194 0 35 0
[pid=7978] ppid=7951 vsize=47728 CPUtime=2.16
/proc/7978/stat : 7978 (aptsolutions.na) R 7951 7951 2059 34821 2220 4202496 11478 0 0 0 210 6 0 0 25 0 1 0 874955644 48873472 11364 1283457024 134512640 134971616 4289238240 18446744073709551615 134964261 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/7978/statm: 11932 11364 204 113 0 11334 0
Current children cumulated CPU time (s) 12.51
Current children cumulated vsize (KiB) 50324

[startup+14.2114 s]
/proc/loadavg: 1.45 1.19 1.09 2/47 7978
/proc/meminfo: memFree=666224/1048576 swapFree=2078760/2097144
[pid=7951] ppid=7950 vsize=2596 CPUtime=10.35
/proc/7951/stat : 7951 (aptitude-parano) S 7950 7951 2059 34821 2220 4202496 721 47628 0 267 0 1 990 44 18 0 1 0 874954459 2658304 294 1283457024 134512640 135304128 4290253488 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7951/statm: 649 294 249 194 0 35 0
[pid=7978] ppid=7951 vsize=52192 CPUtime=2.36
/proc/7978/stat : 7978 (aptsolutions.na) R 7951 7951 2059 34821 2220 4202496 12576 0 0 0 230 6 0 0 25 0 1 0 874955644 53444608 12462 1283457024 134512640 134971616 4289238240 18446744073709551615 134911756 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/7978/statm: 13048 12462 204 113 0 12450 0
Current children cumulated CPU time (s) 12.71
Current children cumulated vsize (KiB) 54788

[startup+14.3114 s]
/proc/loadavg: 1.45 1.19 1.09 2/47 7978
/proc/meminfo: memFree=642664/1048576 swapFree=2078760/2097144
[pid=7951] ppid=7950 vsize=2596 CPUtime=10.35
/proc/7951/stat : 7951 (aptitude-parano) S 7950 7951 2059 34821 2220 4202496 721 47628 0 267 0 1 990 44 18 0 1 0 874954459 2658304 294 1283457024 134512640 135304128 4290253488 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7951/statm: 649 294 249 194 0 35 0
[pid=7978] ppid=7951 vsize=56316 CPUtime=2.46
/proc/7978/stat : 7978 (aptsolutions.na) R 7951 7951 2059 34821 2220 4202496 13558 0 0 0 239 7 0 0 25 0 1 0 874955644 57667584 13444 1283457024 134512640 134971616 4289238240 18446744073709551615 134838926 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/7978/statm: 14079 13444 209 113 0 13481 0
Current children cumulated CPU time (s) 12.81
Current children cumulated vsize (KiB) 58912

Child status: 0
Real time (s): 14.3555
CPU time (s): 12.8648
CPU user time (s): 12.3248
CPU system time (s): 0.540033
CPU usage (%): 89.6159
Max. virtual memory (cumulated for all children) (KiB): 111004

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 12.3248
system time used= 0.540033
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 62657
page faults= 267
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 289
involuntary context switches= 359

runsolver used 0 second user time and 0 second system time

The end