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/201012091704/aspcud-1.3/rand4d6b1c.cudf.difficult.log.runsolver ./aspcud-1.3 /home/misc2010/data/2010/difficult//rand4d6b1c.cudf /home/misc2010/tmp/201012091704/aspcud-1.3/rand4d6b1c.cudf.difficult.result -changed,-notuptodate,-removed,-new 

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.15 1.03 1.01 5/40 5722
/proc/meminfo: memFree=378468/1048576 swapFree=2095372/2097144
[pid=5720] ppid=5719 vsize=2592 CPUtime=0
/proc/5720/stat : 5720 (aspcud-1.3) S 5719 5720 25521 34816 2180 4202496 376 0 0 0 0 0 0 0 18 0 1 0 901283588 2654208 282 1283457024 134512640 135304128 4291315344 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/5720/statm: 648 282 237 194 0 34 0
[pid=5721] ppid=5720 vsize=2592 CPUtime=0
/proc/5721/stat : 5721 (aspcud-1.3) S 5720 5720 25521 34816 2180 4202560 113 0 0 0 0 0 0 0 25 0 1 0 901283588 2654208 129 1283457024 134512640 135304128 4291315344 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/5721/statm: 648 129 83 194 0 34 0
[pid=5722] ppid=5721 vsize=2592 CPUtime=0
/proc/5722/stat : 5722 (aspcud-1.3) R 5721 5720 25521 34816 2180 4202560 126 0 0 0 0 0 0 0 25 0 1 0 901283588 2654208 149 1283457024 134512640 135304128 4291315344 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/5722/statm: 648 149 103 194 0 34 0
[pid=5723] ppid=5722 vsize=2592 CPUtime=0
/proc/5723/stat : 5723 (aspcud-1.3) R 5722 5720 25521 34816 2180 4202560 0 0 0 0 0 0 0 0 25 0 1 0 901283588 2654208 46 1283457024 134512640 135304128 4291315344 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/5723/statm: 648 46 0 194 0 34 0

[startup+0.132993 s]
/proc/loadavg: 1.15 1.03 1.01 5/40 5722
/proc/meminfo: memFree=378468/1048576 swapFree=2095372/2097144
[pid=5720] ppid=5719 vsize=2600 CPUtime=0
/proc/5720/stat : 5720 (aspcud-1.3) S 5719 5720 25521 34816 2180 4202496 573 1505 0 0 0 0 0 0 25 0 1 0 901283588 2662400 300 1283457024 134512640 135304128 4291315344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5720/statm: 650 300 253 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+0.203017 s]
/proc/loadavg: 1.15 1.03 1.01 5/40 5722
/proc/meminfo: memFree=378468/1048576 swapFree=2095372/2097144
[pid=5720] ppid=5719 vsize=2600 CPUtime=0
/proc/5720/stat : 5720 (aspcud-1.3) S 5719 5720 25521 34816 2180 4202496 573 1505 0 0 0 0 0 0 25 0 1 0 901283588 2662400 300 1283457024 134512640 135304128 4291315344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5720/statm: 650 300 253 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+0.313033 s]
/proc/loadavg: 1.15 1.03 1.01 5/40 5722
/proc/meminfo: memFree=378468/1048576 swapFree=2095372/2097144
[pid=5720] ppid=5719 vsize=2600 CPUtime=0
/proc/5720/stat : 5720 (aspcud-1.3) S 5719 5720 25521 34816 2180 4202496 573 1505 0 0 0 0 0 0 25 0 1 0 901283588 2662400 300 1283457024 134512640 135304128 4291315344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5720/statm: 650 300 253 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+0.71314 s]
/proc/loadavg: 1.15 1.03 1.01 5/40 5722
/proc/meminfo: memFree=378468/1048576 swapFree=2095372/2097144
[pid=5720] ppid=5719 vsize=2600 CPUtime=0
/proc/5720/stat : 5720 (aspcud-1.3) S 5719 5720 25521 34816 2180 4202496 573 1505 0 0 0 0 0 0 25 0 1 0 901283588 2662400 300 1283457024 134512640 135304128 4291315344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5720/statm: 650 300 253 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+1.51334 s]
/proc/loadavg: 1.15 1.03 1.01 3/41 5731
/proc/meminfo: memFree=366304/1048576 swapFree=2095372/2097144
[pid=5720] ppid=5719 vsize=2600 CPUtime=1.23
/proc/5720/stat : 5720 (aspcud-1.3) S 5719 5720 25521 34816 2180 4202496 573 15008 0 0 0 0 115 8 16 0 1 0 901283588 2662400 300 1283457024 134512640 135304128 4291315344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5720/statm: 650 300 253 194 0 36 0
[pid=5729] ppid=5720 vsize=15068 CPUtime=0.27
/proc/5729/stat : 5729 (clasp) R 5720 5720 25521 34816 2180 4202496 3962 0 0 0 24 3 0 0 18 0 1 0 901283589 15429632 3363 1283457024 134512640 136223643 4292231008 18446744073709551615 134704872 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5729/statm: 3767 3363 223 418 0 3347 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 17668

[startup+3.11365 s]
/proc/loadavg: 1.15 1.03 1.01 2/40 5731
/proc/meminfo: memFree=365328/1048576 swapFree=2095372/2097144
[pid=5720] ppid=5719 vsize=2600 CPUtime=1.23
/proc/5720/stat : 5720 (aspcud-1.3) S 5719 5720 25521 34816 2180 4202496 573 15008 0 0 0 0 115 8 16 0 1 0 901283588 2662400 300 1283457024 134512640 135304128 4291315344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5720/statm: 650 300 253 194 0 36 0
[pid=5729] ppid=5720 vsize=17612 CPUtime=1.87
/proc/5729/stat : 5729 (clasp) R 5720 5720 25521 34816 2180 4202496 4587 0 0 0 184 3 0 0 20 0 1 0 901283589 18034688 3988 1283457024 134512640 136223643 4292231008 18446744073709551615 134711747 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5729/statm: 4403 3988 225 418 0 3983 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 20212

[startup+6.30437 s]
/proc/loadavg: 1.13 1.03 1.01 2/40 5731
/proc/meminfo: memFree=363344/1048576 swapFree=2095372/2097144
[pid=5720] ppid=5719 vsize=2600 CPUtime=1.23
/proc/5720/stat : 5720 (aspcud-1.3) S 5719 5720 25521 34816 2180 4202496 573 15008 0 0 0 0 115 8 16 0 1 0 901283588 2662400 300 1283457024 134512640 135304128 4291315344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5720/statm: 650 300 253 194 0 36 0
[pid=5729] ppid=5720 vsize=16988 CPUtime=5.05
/proc/5729/stat : 5729 (clasp) R 5720 5720 25521 34816 2180 4202496 4587 0 0 0 502 3 0 0 25 0 1 0 901283589 17395712 3848 1283457024 134512640 136223643 4292231008 18446744073709551615 134704862 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5729/statm: 4247 3848 225 418 0 3827 0
Current children cumulated CPU time (s) 6.28
Current children cumulated vsize (KiB) 19588

[startup+12.7059 s]
/proc/loadavg: 1.12 1.03 1.01 2/40 5731
/proc/meminfo: memFree=360616/1048576 swapFree=2095372/2097144
[pid=5720] ppid=5719 vsize=2600 CPUtime=1.23
/proc/5720/stat : 5720 (aspcud-1.3) S 5719 5720 25521 34816 2180 4202496 573 15008 0 0 0 0 115 8 16 0 1 0 901283588 2662400 300 1283457024 134512640 135304128 4291315344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5720/statm: 650 300 253 194 0 36 0
[pid=5729] ppid=5720 vsize=21220 CPUtime=11.45
/proc/5729/stat : 5729 (clasp) R 5720 5720 25521 34816 2180 4202496 5614 0 0 0 1141 4 0 0 25 0 1 0 901283589 21729280 4875 1283457024 134512640 136223643 4292231008 18446744073709551615 135609367 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5729/statm: 5305 4875 225 418 0 4885 0
Current children cumulated CPU time (s) 12.68
Current children cumulated vsize (KiB) 23820

[startup+25.5083 s]
/proc/loadavg: 1.10 1.03 1.00 2/40 5731
/proc/meminfo: memFree=344620/1048576 swapFree=2095372/2097144
[pid=5720] ppid=5719 vsize=2600 CPUtime=1.23
/proc/5720/stat : 5720 (aspcud-1.3) S 5719 5720 25521 34816 2180 4202496 573 15008 0 0 0 0 115 8 16 0 1 0 901283588 2662400 300 1283457024 134512640 135304128 4291315344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5720/statm: 650 300 253 194 0 36 0
[pid=5729] ppid=5720 vsize=36296 CPUtime=24.24
/proc/5729/stat : 5729 (clasp) R 5720 5720 25521 34816 2180 4202496 9387 0 0 0 2416 8 0 0 25 0 1 0 901283589 37167104 8648 1283457024 134512640 136223643 4292231008 18446744073709551615 134630032 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5729/statm: 9074 8648 225 418 0 8654 0
Current children cumulated CPU time (s) 25.47
Current children cumulated vsize (KiB) 38896

[startup+51.1135 s]
/proc/loadavg: 1.06 1.02 1.00 2/40 5731
/proc/meminfo: memFree=333832/1048576 swapFree=2095372/2097144
[pid=5720] ppid=5719 vsize=2600 CPUtime=1.23
/proc/5720/stat : 5720 (aspcud-1.3) S 5719 5720 25521 34816 2180 4202496 573 15008 0 0 0 0 115 8 16 0 1 0 901283588 2662400 300 1283457024 134512640 135304128 4291315344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5720/statm: 650 300 253 194 0 36 0
[pid=5729] ppid=5720 vsize=47112 CPUtime=49.83
/proc/5729/stat : 5729 (clasp) R 5720 5720 25521 34816 2180 4202496 12079 0 0 0 4975 8 0 0 25 0 1 0 901283589 48242688 11340 1283457024 134512640 136223643 4292231008 18446744073709551615 134920395 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5729/statm: 11778 11340 225 418 0 11358 0
Current children cumulated CPU time (s) 51.06
Current children cumulated vsize (KiB) 49712

[startup+102.306 s]
/proc/loadavg: 1.02 1.02 1.00 2/40 5731
/proc/meminfo: memFree=333708/1048576 swapFree=2095372/2097144
[pid=5720] ppid=5719 vsize=2600 CPUtime=1.23
/proc/5720/stat : 5720 (aspcud-1.3) S 5719 5720 25521 34816 2180 4202496 573 15008 0 0 0 0 115 8 16 0 1 0 901283588 2662400 300 1283457024 134512640 135304128 4291315344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5720/statm: 650 300 253 194 0 36 0
[pid=5729] ppid=5720 vsize=47112 CPUtime=100.95
/proc/5729/stat : 5729 (clasp) R 5720 5720 25521 34816 2180 4202496 12080 0 0 0 10087 8 0 0 25 0 1 0 901283589 48242688 11341 1283457024 134512640 136223643 4292231008 18446744073709551615 134907837 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5729/statm: 11778 11341 225 418 0 11358 0
Current children cumulated CPU time (s) 102.18
Current children cumulated vsize (KiB) 49712

[startup+162.31 s]
/proc/loadavg: 1.01 1.01 1.00 2/40 5731
/proc/meminfo: memFree=325152/1048576 swapFree=2095372/2097144
[pid=5720] ppid=5719 vsize=2600 CPUtime=1.23
/proc/5720/stat : 5720 (aspcud-1.3) S 5719 5720 25521 34816 2180 4202496 573 15008 0 0 0 0 115 8 16 0 1 0 901283588 2662400 300 1283457024 134512640 135304128 4291315344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5720/statm: 650 300 253 194 0 36 0
[pid=5729] ppid=5720 vsize=55608 CPUtime=160.9
/proc/5729/stat : 5729 (clasp) R 5720 5720 25521 34816 2180 4202496 14913 0 0 0 16080 10 0 0 25 0 1 0 901283589 56942592 13449 1283457024 134512640 136223643 4292231008 18446744073709551615 134924357 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5729/statm: 13902 13449 225 418 0 13482 0
Current children cumulated CPU time (s) 162.13
Current children cumulated vsize (KiB) 58208

[startup+222.308 s]
/proc/loadavg: 1.00 1.01 1.00 2/40 5731
/proc/meminfo: memFree=325028/1048576 swapFree=2095372/2097144
[pid=5720] ppid=5719 vsize=2600 CPUtime=1.23
/proc/5720/stat : 5720 (aspcud-1.3) S 5719 5720 25521 34816 2180 4202496 573 15008 0 0 0 0 115 8 16 0 1 0 901283588 2662400 300 1283457024 134512640 135304128 4291315344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5720/statm: 650 300 253 194 0 36 0
[pid=5729] ppid=5720 vsize=55608 CPUtime=220.85
/proc/5729/stat : 5729 (clasp) R 5720 5720 25521 34816 2180 4202496 14913 0 0 0 22075 10 0 0 25 0 1 0 901283589 56942592 13449 1283457024 134512640 136223643 4292231008 18446744073709551615 134712456 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5729/statm: 13902 13449 225 418 0 13482 0
Current children cumulated CPU time (s) 222.08
Current children cumulated vsize (KiB) 58208

[startup+282.31 s]
/proc/loadavg: 1.00 1.00 1.00 2/40 5731
/proc/meminfo: memFree=325028/1048576 swapFree=2095372/2097144
[pid=5720] ppid=5719 vsize=2600 CPUtime=1.23
/proc/5720/stat : 5720 (aspcud-1.3) S 5719 5720 25521 34816 2180 4202496 573 15008 0 0 0 0 115 8 16 0 1 0 901283588 2662400 300 1283457024 134512640 135304128 4291315344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5720/statm: 650 300 253 194 0 36 0
[pid=5729] ppid=5720 vsize=55608 CPUtime=280.83
/proc/5729/stat : 5729 (clasp) R 5720 5720 25521 34816 2180 4202496 14914 0 0 0 28073 10 0 0 25 0 1 0 901283589 56942592 13450 1283457024 134512640 136223643 4292231008 18446744073709551615 134929219 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5729/statm: 13902 13450 225 418 0 13482 0
Current children cumulated CPU time (s) 282.06
Current children cumulated vsize (KiB) 58208



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.302 s]
/proc/loadavg: 1.00 1.00 1.00 2/40 5731
/proc/meminfo: memFree=324036/1048576 swapFree=2095372/2097144
[pid=5720] ppid=5719 vsize=2600 CPUtime=1.23
/proc/5720/stat : 5720 (aspcud-1.3) S 5719 5720 25521 34816 2180 4202496 573 15008 0 0 0 0 115 8 16 0 1 0 901283588 2662400 300 1283457024 134512640 135304128 4291315344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5720/statm: 650 300 253 194 0 36 0
[pid=5729] ppid=5720 vsize=55852 CPUtime=288.81
/proc/5729/stat : 5729 (clasp) R 5720 5720 25521 34816 2180 4202496 15237 0 0 0 28871 10 0 0 25 0 1 0 901283589 57192448 13535 1283457024 134512640 136223643 4292231008 18446744073709551615 134929006 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5729/statm: 13963 13535 225 418 0 13543 0
Current children cumulated CPU time (s) 290.04
Current children cumulated vsize (KiB) 58452

Sending User defined signal 1 to process tree (bottom up)
Sleeping 10 seconds

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

Child status: 0
Real time (s): 290.324
CPU time (s): 290.082
CPU user time (s): 289.886
CPU system time (s): 0.196012
CPU usage (%): 99.9166
Max. virtual memory (cumulated for all children) (KiB): 59528

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 289.886
system time used= 0.196012
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 33423
page faults= 0
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 444
involuntary context switches= 3954

runsolver used 0 second user time and 0.008 second system time

The end