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/rand95e48b.cudf.difficult.log.runsolver ./aptitude-paranoid-1.0 /home/misc2010/data/2010/difficult//rand95e48b.cudf /home/misc2010/tmp/201012061533/aptitude-paranoid-1.0/rand95e48b.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.30 1.29 1.21 3/46 29789
/proc/meminfo: memFree=780572/1048576 swapFree=2078744/2097144
[pid=29788] ppid=29787 vsize=2572 CPUtime=0
/proc/29788/stat : 29788 (aptitude-parano) R 29787 29788 2059 34821 2220 4202496 359 0 0 0 0 0 0 0 25 0 1 0 876519418 2633728 272 1283457024 134512640 135304128 4287839056 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/29788/statm: 643 272 232 194 0 29 0
[pid=29789] ppid=29788 vsize=2572 CPUtime=0
/proc/29789/stat : 29789 (aptitude-parano) R 29788 29788 2059 34821 2220 4202560 0 0 0 0 0 0 0 0 25 0 1 0 876519418 2633728 40 1283457024 134512640 135304128 4287839056 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/29789/statm: 643 40 0 194 0 29 0

[startup+0.115813 s]
/proc/loadavg: 1.30 1.29 1.21 3/46 29789
/proc/meminfo: memFree=780572/1048576 swapFree=2078744/2097144
[pid=29788] ppid=29787 vsize=2584 CPUtime=0.04
/proc/29788/stat : 29788 (aptitude-parano) R 29787 29788 2059 34821 2220 4202496 548 1858 0 0 0 0 0 4 25 0 1 0 876519418 2646016 283 1283457024 134512640 135304128 4287839056 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/29788/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 2584

[startup+0.215857 s]
/proc/loadavg: 1.30 1.29 1.21 3/46 29789
/proc/meminfo: memFree=780572/1048576 swapFree=2078744/2097144
[pid=29788] ppid=29787 vsize=2584 CPUtime=0.04
/proc/29788/stat : 29788 (aptitude-parano) S 29787 29788 2059 34821 2220 4202496 566 1858 0 0 0 0 0 4 25 0 1 0 876519418 2646016 283 1283457024 134512640 135304128 4287839056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29788/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 2584

[startup+0.315878 s]
/proc/loadavg: 1.30 1.29 1.21 3/46 29789
/proc/meminfo: memFree=780572/1048576 swapFree=2078744/2097144
[pid=29788] ppid=29787 vsize=2584 CPUtime=0.04
/proc/29788/stat : 29788 (aptitude-parano) S 29787 29788 2059 34821 2220 4202496 566 1858 0 0 0 0 0 4 25 0 1 0 876519418 2646016 283 1283457024 134512640 135304128 4287839056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29788/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 2584

[startup+0.715958 s]
/proc/loadavg: 1.30 1.29 1.21 3/46 29789
/proc/meminfo: memFree=780572/1048576 swapFree=2078744/2097144
[pid=29788] ppid=29787 vsize=2584 CPUtime=0.04
/proc/29788/stat : 29788 (aptitude-parano) S 29787 29788 2059 34821 2220 4202496 566 1858 0 0 0 0 0 4 25 0 1 0 876519418 2646016 283 1283457024 134512640 135304128 4287839056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29788/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 2584

[startup+1.50619 s]
/proc/loadavg: 1.30 1.29 1.21 2/47 29799
/proc/meminfo: memFree=745884/1048576 swapFree=2078744/2097144
[pid=29788] ppid=29787 vsize=2584 CPUtime=0.04
/proc/29788/stat : 29788 (aptitude-parano) S 29787 29788 2059 34821 2220 4202496 566 1858 0 0 0 0 0 4 25 0 1 0 876519418 2646016 283 1283457024 134512640 135304128 4287839056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29788/statm: 646 283 240 194 0 32 0
[pid=29799] ppid=29788 vsize=32760 CPUtime=1.46
/proc/29799/stat : 29799 (cudftodeb.nativ) R 29788 29788 2059 34821 2220 4202496 7777 0 0 0 142 4 0 0 25 0 1 0 876519422 33546240 7704 1283457024 134512640 135004320 4288179184 18446744073709551615 134996707 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/29799/statm: 8190 7704 225 121 0 7582 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 35344

[startup+3.10658 s]
/proc/loadavg: 1.30 1.29 1.21 2/47 29799
/proc/meminfo: memFree=724184/1048576 swapFree=2078744/2097144
[pid=29788] ppid=29787 vsize=2584 CPUtime=0.04
/proc/29788/stat : 29788 (aptitude-parano) S 29787 29788 2059 34821 2220 4202496 566 1858 0 0 0 0 0 4 25 0 1 0 876519418 2646016 283 1283457024 134512640 135304128 4287839056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29788/statm: 646 283 240 194 0 32 0
[pid=29799] ppid=29788 vsize=66868 CPUtime=3.06
/proc/29799/stat : 29799 (cudftodeb.nativ) R 29788 29788 2059 34821 2220 4202496 16172 0 0 0 301 5 0 0 25 0 1 0 876519422 68472832 16099 1283457024 134512640 135004320 4288179184 18446744073709551615 134996526 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/29799/statm: 16717 16099 237 121 0 16109 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 69452

[startup+6.30413 s]
/proc/loadavg: 1.28 1.28 1.21 2/47 29799
/proc/meminfo: memFree=665160/1048576 swapFree=2078744/2097144
[pid=29788] ppid=29787 vsize=2592 CPUtime=5.65
/proc/29788/stat : 29788 (aptitude-parano) S 29787 29788 2059 34821 2220 4202496 649 25892 0 0 0 0 547 18 18 0 1 0 876519418 2654208 286 1283457024 134512640 135304128 4287839056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29788/statm: 648 286 241 194 0 34 0
Current children cumulated CPU time (s) 5.65
Current children cumulated vsize (KiB) 2592

[startup+12.7092 s]
/proc/loadavg: 1.25 1.28 1.21 2/48 29813
/proc/meminfo: memFree=675088/1048576 swapFree=2078744/2097144
[pid=29788] ppid=29787 vsize=2592 CPUtime=5.88
/proc/29788/stat : 29788 (aptitude-parano) S 29787 29788 2059 34821 2220 4202496 695 28292 0 1 0 0 568 20 19 0 1 0 876519418 2654208 294 1283457024 134512640 135304128 4287839056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29788/statm: 648 294 249 194 0 34 0
[pid=29809] ppid=29788 vsize=66348 CPUtime=5.2
/proc/29809/stat : 29809 (aptitude) R 29788 29788 2059 34821 2220 4202496 19164 1060 266 0 508 12 0 0 25 0 2 0 876520068 67940352 10910 1283457024 134512640 137933492 4291523232 18446744073709551615 4159796717 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/29809/statm: 16587 10910 5754 836 0 9219 0
[pid=29809/tid=29811] ppid=29788 vsize=66348 CPUtime=1.09
/proc/29809/task/29811/stat : 29811 (aptitude) S 29788 29788 2059 34821 2220 4202560 2661 1060 0 0 109 0 0 0 16 0 2 0 876520295 67940352 10910 1283457024 134512640 137933492 4291523232 18446744073709551615 4294960130 0 134217728 4096 0 18446612132680193024 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 11.08
Current children cumulated vsize (KiB) 68940

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

[startup+12.8092 s]
/proc/loadavg: 1.25 1.28 1.21 2/48 29813
/proc/meminfo: memFree=675088/1048576 swapFree=2078744/2097144
[pid=29788] ppid=29787 vsize=2592 CPUtime=11.15
/proc/29788/stat : 29788 (aptitude-parano) R 29787 29788 2059 34821 2220 4202496 705 48616 0 267 0 0 1081 34 18 0 1 0 876519418 2654208 294 1283457024 134512640 135304128 4287839056 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/29788/statm: 648 294 249 194 0 34 0
Current children cumulated CPU time (s) 11.15
Current children cumulated vsize (KiB) 2592

[startup+14.4096 s]
/proc/loadavg: 1.23 1.27 1.20 2/47 29815
/proc/meminfo: memFree=662696/1048576 swapFree=2078744/2097144
[pid=29788] ppid=29787 vsize=2592 CPUtime=11.15
/proc/29788/stat : 29788 (aptitude-parano) S 29787 29788 2059 34821 2220 4202496 722 48616 0 267 0 0 1081 34 18 0 1 0 876519418 2654208 294 1283457024 134512640 135304128 4287839056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29788/statm: 648 294 249 194 0 34 0
[pid=29815] ppid=29788 vsize=38056 CPUtime=1.64
/proc/29815/stat : 29815 (aptsolutions.na) R 29788 29788 2059 34821 2220 4202496 9074 0 0 0 163 1 0 0 25 0 1 0 876520694 38969344 8961 1283457024 134512640 134971616 4290221520 18446744073709551615 134915762 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/29815/statm: 9514 8961 204 113 0 8916 0
Current children cumulated CPU time (s) 12.79
Current children cumulated vsize (KiB) 40648

[startup+14.8097 s]
/proc/loadavg: 1.23 1.27 1.20 2/47 29815
/proc/meminfo: memFree=662696/1048576 swapFree=2078744/2097144
[pid=29788] ppid=29787 vsize=2592 CPUtime=11.15
/proc/29788/stat : 29788 (aptitude-parano) S 29787 29788 2059 34821 2220 4202496 722 48616 0 267 0 0 1081 34 18 0 1 0 876519418 2654208 294 1283457024 134512640 135304128 4287839056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29788/statm: 648 294 249 194 0 34 0
[pid=29815] ppid=29788 vsize=45992 CPUtime=2.04
/proc/29815/stat : 29815 (aptsolutions.na) R 29788 29788 2059 34821 2220 4202496 10986 0 0 0 202 2 0 0 25 0 1 0 876520694 47095808 10873 1283457024 134512640 134971616 4290221520 18446744073709551615 134627824 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/29815/statm: 11498 10873 204 113 0 10900 0
Current children cumulated CPU time (s) 13.19
Current children cumulated vsize (KiB) 48584

[startup+15.2098 s]
/proc/loadavg: 1.23 1.27 1.20 2/47 29815
/proc/meminfo: memFree=662696/1048576 swapFree=2078744/2097144
[pid=29788] ppid=29787 vsize=2592 CPUtime=11.15
/proc/29788/stat : 29788 (aptitude-parano) S 29787 29788 2059 34821 2220 4202496 722 48616 0 267 0 0 1081 34 18 0 1 0 876519418 2654208 294 1283457024 134512640 135304128 4287839056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29788/statm: 648 294 249 194 0 34 0
[pid=29815] ppid=29788 vsize=56812 CPUtime=2.44
/proc/29815/stat : 29815 (aptsolutions.na) R 29788 29788 2059 34821 2220 4202496 13715 0 0 0 242 2 0 0 25 0 1 0 876520694 58175488 13602 1283457024 134512640 134971616 4290221520 18446744073709551615 134835886 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/29815/statm: 14203 13602 209 113 0 13605 0
Current children cumulated CPU time (s) 13.59
Current children cumulated vsize (KiB) 59404

Child status: 0
Real time (s): 15.2304
CPU time (s): 13.6208
CPU user time (s): 13.2448
CPU system time (s): 0.376023
CPU usage (%): 89.4322
Max. virtual memory (cumulated for all children) (KiB): 111000

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 13.2448
system time used= 0.376023
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 63502
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= 346
involuntary context switches= 396

runsolver used 0 second user time and 0 second system time

The end