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/aspcud-trendy-1.3/rand14ba69.cudf.difficult.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/2010/difficult//rand14ba69.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/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.02 1.01 1.00 1/40 10024
/proc/meminfo: memFree=925104/1048576 swapFree=2077144/2097144
[pid=10024] ppid=10023 vsize=3028 CPUtime=0
/proc/10024/stat : 10024 (runsolver) D 10023 10024 4159 34819 4229 4202560 73 0 0 0 0 0 0 0 25 0 1 0 879066122 3100672 94 1283457024 134512640 134586868 4293482480 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/10024/statm: 757 94 62 19 0 55 0

[startup+0.154866 s]
/proc/loadavg: 1.02 1.01 1.00 1/40 10024
/proc/meminfo: memFree=925104/1048576 swapFree=2077144/2097144
[pid=10024] ppid=10023 vsize=2600 CPUtime=0
/proc/10024/stat : 10024 (aspcud-trendy-1) S 10023 10024 4159 34819 4229 4202496 619 2219 0 3 0 0 0 0 25 0 1 0 879066122 2662400 301 1283457024 134512640 135304128 4291936064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10024/statm: 650 301 253 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+0.206818 s]
/proc/loadavg: 1.02 1.01 1.00 1/40 10024
/proc/meminfo: memFree=925104/1048576 swapFree=2077144/2097144
[pid=10024] ppid=10023 vsize=2600 CPUtime=0
/proc/10024/stat : 10024 (aspcud-trendy-1) S 10023 10024 4159 34819 4229 4202496 619 2219 0 3 0 0 0 0 25 0 1 0 879066122 2662400 301 1283457024 134512640 135304128 4291936064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10024/statm: 650 301 253 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+0.31502 s]
/proc/loadavg: 1.02 1.01 1.00 1/40 10024
/proc/meminfo: memFree=925104/1048576 swapFree=2077144/2097144
[pid=10024] ppid=10023 vsize=2600 CPUtime=0
/proc/10024/stat : 10024 (aspcud-trendy-1) S 10023 10024 4159 34819 4229 4202496 619 2219 0 3 0 0 0 0 25 0 1 0 879066122 2662400 301 1283457024 134512640 135304128 4291936064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10024/statm: 650 301 253 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+0.715141 s]
/proc/loadavg: 1.02 1.01 1.00 1/40 10024
/proc/meminfo: memFree=925104/1048576 swapFree=2077144/2097144
[pid=10024] ppid=10023 vsize=2600 CPUtime=0
/proc/10024/stat : 10024 (aspcud-trendy-1) S 10023 10024 4159 34819 4229 4202496 619 2219 0 3 0 0 0 0 25 0 1 0 879066122 2662400 301 1283457024 134512640 135304128 4291936064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10024/statm: 650 301 253 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+1.51536 s]
/proc/loadavg: 1.02 1.01 1.00 3/44 10038
/proc/meminfo: memFree=886488/1048576 swapFree=2077144/2097144
[pid=10024] ppid=10023 vsize=2600 CPUtime=0.92
/proc/10024/stat : 10024 (aspcud-trendy-1) S 10023 10024 4159 34819 4229 4202496 619 11423 0 18 0 0 82 10 18 0 1 0 879066122 2662400 301 1283457024 134512640 135304128 4291936064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10024/statm: 650 301 253 194 0 36 0
[pid=10036] ppid=10024 vsize=9756 CPUtime=0.03
/proc/10036/stat : 10036 (clasp) R 10024 10024 4159 34819 4229 4202496 2500 0 18 0 3 0 0 0 18 0 1 0 879066126 9990144 2181 1283457024 134512640 136223643 4289747680 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/10036/statm: 2439 2181 174 418 0 2019 0
[pid=10037] ppid=10024 vsize=15228 CPUtime=0.34
/proc/10037/stat : 10037 (gringo) R 10024 10024 4159 34819 4229 4202496 3835 0 22 0 32 2 0 0 18 0 1 0 879066126 15593472 2968 1283457024 134512640 136959103 4292267600 18446744073709551615 134740718 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/10037/statm: 3807 2968 256 598 0 3206 0
Current children cumulated CPU time (s) 1.29
Current children cumulated vsize (KiB) 27584

[startup+3.1061 s]
/proc/loadavg: 1.02 1.01 1.00 2/42 10038
/proc/meminfo: memFree=899480/1048576 swapFree=2077144/2097144
[pid=10024] ppid=10023 vsize=2600 CPUtime=1.6
/proc/10024/stat : 10024 (aspcud-trendy-1) S 10023 10024 4159 34819 4229 4202496 619 18438 0 40 0 0 145 15 15 0 1 0 879066122 2662400 301 1283457024 134512640 135304128 4291936064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10024/statm: 650 301 253 194 0 36 0
[pid=10036] ppid=10024 vsize=23120 CPUtime=1.28
/proc/10036/stat : 10036 (clasp) R 10024 10024 4159 34819 4229 4202496 6156 0 19 0 128 0 0 0 19 0 1 0 879066126 23674880 5236 1283457024 134512640 136223643 4289747680 18446744073709551615 134711220 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/10036/statm: 5780 5236 225 418 0 5360 0
Current children cumulated CPU time (s) 2.88
Current children cumulated vsize (KiB) 25720

[startup+6.30677 s]
/proc/loadavg: 1.01 1.01 1.00 2/42 10038
/proc/meminfo: memFree=893288/1048576 swapFree=2077144/2097144
[pid=10024] ppid=10023 vsize=2600 CPUtime=1.6
/proc/10024/stat : 10024 (aspcud-trendy-1) S 10023 10024 4159 34819 4229 4202496 619 18438 0 40 0 0 145 15 15 0 1 0 879066122 2662400 301 1283457024 134512640 135304128 4291936064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10024/statm: 650 301 253 194 0 36 0
[pid=10036] ppid=10024 vsize=29736 CPUtime=4.47
/proc/10036/stat : 10036 (clasp) R 10024 10024 4159 34819 4229 4202496 7822 0 19 0 446 1 0 0 25 0 1 0 879066126 30449664 6902 1283457024 134512640 136223643 4289747680 18446744073709551615 134711275 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/10036/statm: 7434 6902 225 418 0 7014 0
Current children cumulated CPU time (s) 6.07
Current children cumulated vsize (KiB) 32336

[startup+12.7081 s]
/proc/loadavg: 1.01 1.01 1.00 2/42 10038
/proc/meminfo: memFree=865760/1048576 swapFree=2077144/2097144
[pid=10024] ppid=10023 vsize=2600 CPUtime=1.6
/proc/10024/stat : 10024 (aspcud-trendy-1) S 10023 10024 4159 34819 4229 4202496 619 18438 0 40 0 0 145 15 15 0 1 0 879066122 2662400 301 1283457024 134512640 135304128 4291936064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10024/statm: 650 301 253 194 0 36 0
[pid=10036] ppid=10024 vsize=57128 CPUtime=10.87
/proc/10036/stat : 10036 (clasp) R 10024 10024 4159 34819 4229 4202496 14664 0 19 0 1082 5 0 0 25 0 1 0 879066126 58499072 13744 1283457024 134512640 136223643 4289747680 18446744073709551615 134651087 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/10036/statm: 14282 13744 225 418 0 13862 0
Current children cumulated CPU time (s) 12.47
Current children cumulated vsize (KiB) 59728

[startup+25.511 s]
/proc/loadavg: 1.01 1.01 1.00 2/42 10038
/proc/meminfo: memFree=860676/1048576 swapFree=2077144/2097144
[pid=10024] ppid=10023 vsize=2600 CPUtime=1.6
/proc/10024/stat : 10024 (aspcud-trendy-1) S 10023 10024 4159 34819 4229 4202496 619 18438 0 40 0 0 145 15 15 0 1 0 879066122 2662400 301 1283457024 134512640 135304128 4291936064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10024/statm: 650 301 253 194 0 36 0
[pid=10036] ppid=10024 vsize=63616 CPUtime=23.66
/proc/10036/stat : 10036 (clasp) R 10024 10024 4159 34819 4229 4202496 16273 0 19 0 2360 6 0 0 25 0 1 0 879066126 65142784 15353 1283457024 134512640 136223643 4289747680 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/10036/statm: 15904 15353 225 418 0 15484 0
Current children cumulated CPU time (s) 25.26
Current children cumulated vsize (KiB) 66216

[startup+51.1089 s]
/proc/loadavg: 1.00 1.00 1.00 2/42 10038
/proc/meminfo: memFree=817152/1048576 swapFree=2077144/2097144
[pid=10024] ppid=10023 vsize=2600 CPUtime=1.6
/proc/10024/stat : 10024 (aspcud-trendy-1) S 10023 10024 4159 34819 4229 4202496 619 18438 0 40 0 0 145 15 15 0 1 0 879066122 2662400 301 1283457024 134512640 135304128 4291936064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10024/statm: 650 301 253 194 0 36 0
[pid=10036] ppid=10024 vsize=105832 CPUtime=49.23
/proc/10036/stat : 10036 (clasp) R 10024 10024 4159 34819 4229 4202496 26784 0 19 0 4911 12 0 0 25 0 1 0 879066126 108371968 25864 1283457024 134512640 136223643 4289747680 18446744073709551615 135628159 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/10036/statm: 26458 25864 225 418 0 26038 0
Current children cumulated CPU time (s) 50.83
Current children cumulated vsize (KiB) 108432

[startup+102.312 s]
/proc/loadavg: 1.00 1.00 1.00 2/42 10038
/proc/meminfo: memFree=807356/1048576 swapFree=2077144/2097144
[pid=10024] ppid=10023 vsize=2600 CPUtime=1.6
/proc/10024/stat : 10024 (aspcud-trendy-1) S 10023 10024 4159 34819 4229 4202496 619 18438 0 40 0 0 145 15 15 0 1 0 879066122 2662400 301 1283457024 134512640 135304128 4291936064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10024/statm: 650 301 253 194 0 36 0
[pid=10036] ppid=10024 vsize=115388 CPUtime=100.4
/proc/10036/stat : 10036 (clasp) R 10024 10024 4159 34819 4229 4202496 29870 0 19 0 10025 15 0 0 25 0 1 0 879066126 118157312 28294 1283457024 134512640 136223643 4289747680 18446744073709551615 134704872 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/10036/statm: 28847 28294 225 418 0 28427 0
Current children cumulated CPU time (s) 102
Current children cumulated vsize (KiB) 117988

[startup+162.309 s]
/proc/loadavg: 1.00 1.00 1.00 2/42 10038
/proc/meminfo: memFree=806364/1048576 swapFree=2077144/2097144
[pid=10024] ppid=10023 vsize=2600 CPUtime=1.6
/proc/10024/stat : 10024 (aspcud-trendy-1) S 10023 10024 4159 34819 4229 4202496 619 18438 0 40 0 0 145 15 15 0 1 0 879066122 2662400 301 1283457024 134512640 135304128 4291936064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10024/statm: 650 301 253 194 0 36 0
[pid=10036] ppid=10024 vsize=116268 CPUtime=160.35
/proc/10036/stat : 10036 (clasp) R 10024 10024 4159 34819 4229 4202496 30452 0 19 0 16019 16 0 0 25 0 1 0 879066126 119058432 28528 1283457024 134512640 136223643 4289747680 18446744073709551615 134928869 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/10036/statm: 29067 28528 225 418 0 28647 0
Current children cumulated CPU time (s) 161.95
Current children cumulated vsize (KiB) 118868

[startup+222.305 s]
/proc/loadavg: 1.00 1.00 1.00 2/42 10038
/proc/meminfo: memFree=804380/1048576 swapFree=2077144/2097144
[pid=10024] ppid=10023 vsize=2600 CPUtime=1.6
/proc/10024/stat : 10024 (aspcud-trendy-1) S 10023 10024 4159 34819 4229 4202496 619 18438 0 40 0 0 145 15 15 0 1 0 879066122 2662400 301 1283457024 134512640 135304128 4291936064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10024/statm: 650 301 253 194 0 36 0
[pid=10036] ppid=10024 vsize=117912 CPUtime=220.3
/proc/10036/stat : 10036 (clasp) R 10024 10024 4159 34819 4229 4202496 30977 0 19 0 22012 18 0 0 25 0 1 0 879066126 120741888 28924 1283457024 134512640 136223643 4289747680 18446744073709551615 134711214 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/10036/statm: 29478 28924 225 418 0 29058 0
Current children cumulated CPU time (s) 221.9
Current children cumulated vsize (KiB) 120512

[startup+282.307 s]
/proc/loadavg: 1.00 1.00 1.00 2/42 10038
/proc/meminfo: memFree=804380/1048576 swapFree=2077144/2097144
[pid=10024] ppid=10023 vsize=2600 CPUtime=1.6
/proc/10024/stat : 10024 (aspcud-trendy-1) S 10023 10024 4159 34819 4229 4202496 619 18438 0 40 0 0 145 15 15 0 1 0 879066122 2662400 301 1283457024 134512640 135304128 4291936064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10024/statm: 650 301 253 194 0 36 0
[pid=10036] ppid=10024 vsize=117912 CPUtime=280.19
/proc/10036/stat : 10036 (clasp) R 10024 10024 4159 34819 4229 4202496 30977 0 19 0 27999 20 0 0 25 0 1 0 879066126 120741888 28924 1283457024 134512640 136223643 4289747680 18446744073709551615 134664680 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/10036/statm: 29478 28924 225 418 0 29058 0
Current children cumulated CPU time (s) 281.79
Current children cumulated vsize (KiB) 120512



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.609 s]
/proc/loadavg: 1.00 1.00 1.00 2/42 10038
/proc/meminfo: memFree=804380/1048576 swapFree=2077144/2097144
[pid=10024] ppid=10023 vsize=2600 CPUtime=1.6
/proc/10024/stat : 10024 (aspcud-trendy-1) S 10023 10024 4159 34819 4229 4202496 619 18438 0 40 0 0 145 15 15 0 1 0 879066122 2662400 301 1283457024 134512640 135304128 4291936064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10024/statm: 650 301 253 194 0 36 0
[pid=10036] ppid=10024 vsize=117912 CPUtime=288.49
/proc/10036/stat : 10036 (clasp) R 10024 10024 4159 34819 4229 4202496 30977 0 19 0 28829 20 0 0 25 0 1 0 879066126 120741888 28924 1283457024 134512640 136223643 4289747680 18446744073709551615 134920354 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/10036/statm: 29478 28924 225 418 0 29058 0
Current children cumulated CPU time (s) 290.09
Current children cumulated vsize (KiB) 120512

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

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

[startup+290.609 s]
/proc/loadavg: 1.00 1.00 1.00 2/42 10038
/proc/meminfo: memFree=804380/1048576 swapFree=2077144/2097144
[pid=10024] ppid=10023 vsize=2600 CPUtime=1.6
/proc/10024/stat : 10024 (aspcud-trendy-1) S 10023 10024 4159 34819 4229 4202496 619 18438 0 40 0 0 145 15 15 0 1 0 879066122 2662400 301 1283457024 134512640 135304128 4291936064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10024/statm: 650 301 253 194 0 36 0
[pid=10036] ppid=10024 vsize=117912 CPUtime=288.49
/proc/10036/stat : 10036 (clasp) R 10024 10024 4159 34819 4229 4202496 30977 0 19 0 28829 20 0 0 25 0 1 0 879066126 120741888 28924 1283457024 134512640 136223643 4289747680 18446744073709551615 134920354 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/10036/statm: 29478 28924 225 418 0 29058 0
Current children cumulated CPU time (s) 290.09
Current children cumulated vsize (KiB) 120512

Child status: 0
Real time (s): 290.652
CPU time (s): 290.122
CPU user time (s): 289.754
CPU system time (s): 0.368023
CPU usage (%): 99.8176
Max. virtual memory (cumulated for all children) (KiB): 120980

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 289.754
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= 52638
page faults= 60
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 777
involuntary context switches= 4052

runsolver used 0.004 second user time and 0 second system time

The end