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/rand06f749.cudf.difficult.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/2010/difficult//rand06f749.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand06f749.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.16 1.04 0.79 2/43 4898
/proc/meminfo: memFree=886720/1048576 swapFree=2084088/2097144
[pid=4898] ppid=4897 vsize=3028 CPUtime=0
/proc/4898/stat : 4898 (runsolver) D 4897 4898 4159 34819 4229 4202560 73 0 0 0 0 0 0 0 25 0 1 0 877645057 3100672 94 1283457024 134512640 134586868 4290606384 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/4898/statm: 757 94 62 19 0 55 0

[startup+0.136237 s]
/proc/loadavg: 1.16 1.04 0.79 2/43 4898
/proc/meminfo: memFree=886720/1048576 swapFree=2084088/2097144
[pid=4898] ppid=4897 vsize=2600 CPUtime=0
/proc/4898/stat : 4898 (aspcud-trendy-1) S 4897 4898 4159 34819 4229 4202496 619 2217 0 3 0 0 0 0 25 0 1 0 877645057 2662400 301 1283457024 134512640 135304128 4292259728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4898/statm: 650 301 253 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+0.204228 s]
/proc/loadavg: 1.16 1.04 0.79 2/43 4898
/proc/meminfo: memFree=886720/1048576 swapFree=2084088/2097144
[pid=4898] ppid=4897 vsize=2600 CPUtime=0
/proc/4898/stat : 4898 (aspcud-trendy-1) S 4897 4898 4159 34819 4229 4202496 619 2217 0 3 0 0 0 0 25 0 1 0 877645057 2662400 301 1283457024 134512640 135304128 4292259728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4898/statm: 650 301 253 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+0.304785 s]
/proc/loadavg: 1.16 1.04 0.79 2/43 4898
/proc/meminfo: memFree=886720/1048576 swapFree=2084088/2097144
[pid=4898] ppid=4897 vsize=2600 CPUtime=0
/proc/4898/stat : 4898 (aspcud-trendy-1) S 4897 4898 4159 34819 4229 4202496 619 2217 0 3 0 0 0 0 25 0 1 0 877645057 2662400 301 1283457024 134512640 135304128 4292259728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4898/statm: 650 301 253 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+0.704883 s]
/proc/loadavg: 1.16 1.04 0.79 2/43 4898
/proc/meminfo: memFree=886720/1048576 swapFree=2084088/2097144
[pid=4898] ppid=4897 vsize=2600 CPUtime=0
/proc/4898/stat : 4898 (aspcud-trendy-1) S 4897 4898 4159 34819 4229 4202496 619 2217 0 3 0 0 0 0 25 0 1 0 877645057 2662400 301 1283457024 134512640 135304128 4292259728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4898/statm: 650 301 253 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+1.5095 s]
/proc/loadavg: 1.16 1.04 0.79 3/47 4912
/proc/meminfo: memFree=847044/1048576 swapFree=2084088/2097144
[pid=4898] ppid=4897 vsize=2600 CPUtime=0.88
/proc/4898/stat : 4898 (aspcud-trendy-1) S 4897 4898 4159 34819 4229 4202496 619 11421 0 18 0 0 84 4 18 0 1 0 877645057 2662400 301 1283457024 134512640 135304128 4292259728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4898/statm: 650 301 253 194 0 36 0
[pid=4910] ppid=4898 vsize=10908 CPUtime=0.04
/proc/4910/stat : 4910 (clasp) R 4898 4898 4159 34819 4229 4202496 2874 0 18 0 4 0 0 0 18 0 1 0 877645062 11169792 2373 1283457024 134512640 136223643 4289318016 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4910/statm: 2727 2373 174 418 0 2307 0
[pid=4911] ppid=4898 vsize=17324 CPUtime=0.36
/proc/4911/stat : 4911 (gringo) R 4898 4898 4159 34819 4229 4202496 4244 0 22 0 36 0 0 0 18 0 1 0 877645062 17739776 3377 1283457024 134512640 136959103 4290545200 18446744073709551615 134924630 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4911/statm: 4331 3377 256 598 0 3730 0
Current children cumulated CPU time (s) 1.28
Current children cumulated vsize (KiB) 30832

[startup+3.10983 s]
/proc/loadavg: 1.16 1.04 0.79 2/45 4912
/proc/meminfo: memFree=861400/1048576 swapFree=2084088/2097144
[pid=4898] ppid=4897 vsize=2600 CPUtime=1.5
/proc/4898/stat : 4898 (aspcud-trendy-1) S 4897 4898 4159 34819 4229 4202496 619 18318 0 40 0 0 146 4 15 0 1 0 877645057 2662400 301 1283457024 134512640 135304128 4292259728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4898/statm: 650 301 253 194 0 36 0
[pid=4910] ppid=4898 vsize=22496 CPUtime=1.38
/proc/4910/stat : 4910 (clasp) R 4898 4898 4159 34819 4229 4202496 6009 0 19 0 137 1 0 0 19 0 1 0 877645062 23035904 5101 1283457024 134512640 136223643 4289318016 18446744073709551615 134631716 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4910/statm: 5624 5101 225 418 0 5204 0
Current children cumulated CPU time (s) 2.88
Current children cumulated vsize (KiB) 25096

[startup+6.31045 s]
/proc/loadavg: 1.15 1.04 0.79 2/45 4912
/proc/meminfo: memFree=861152/1048576 swapFree=2084088/2097144
[pid=4898] ppid=4897 vsize=2600 CPUtime=1.5
/proc/4898/stat : 4898 (aspcud-trendy-1) S 4897 4898 4159 34819 4229 4202496 619 18318 0 40 0 0 146 4 15 0 1 0 877645057 2662400 301 1283457024 134512640 135304128 4292259728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4898/statm: 650 301 253 194 0 36 0
[pid=4910] ppid=4898 vsize=25176 CPUtime=4.58
/proc/4910/stat : 4910 (clasp) R 4898 4898 4159 34819 4229 4202496 6681 0 19 0 456 2 0 0 25 0 1 0 877645062 25780224 5773 1283457024 134512640 136223643 4289318016 18446744073709551615 134711295 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4910/statm: 6294 5773 225 418 0 5874 0
Current children cumulated CPU time (s) 6.08
Current children cumulated vsize (KiB) 27776

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

[startup+6.41047 s]
/proc/loadavg: 1.15 1.04 0.79 2/45 4912
/proc/meminfo: memFree=861152/1048576 swapFree=2084088/2097144
[pid=4898] ppid=4897 vsize=2600 CPUtime=1.5
/proc/4898/stat : 4898 (aspcud-trendy-1) S 4897 4898 4159 34819 4229 4202496 619 18318 0 40 0 0 146 4 15 0 1 0 877645057 2662400 301 1283457024 134512640 135304128 4292259728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4898/statm: 650 301 253 194 0 36 0
[pid=4910] ppid=4898 vsize=25176 CPUtime=4.68
/proc/4910/stat : 4910 (clasp) R 4898 4898 4159 34819 4229 4202496 6681 0 19 0 466 2 0 0 25 0 1 0 877645062 25780224 5773 1283457024 134512640 136223643 4289318016 18446744073709551615 135449788 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4910/statm: 6294 5773 225 418 0 5874 0
Current children cumulated CPU time (s) 6.18
Current children cumulated vsize (KiB) 27776

[startup+8.01074 s]
/proc/loadavg: 1.15 1.04 0.79 2/45 4912
/proc/meminfo: memFree=857804/1048576 swapFree=2084088/2097144
[pid=4898] ppid=4897 vsize=2600 CPUtime=1.5
/proc/4898/stat : 4898 (aspcud-trendy-1) S 4897 4898 4159 34819 4229 4202496 619 18318 0 40 0 0 146 4 15 0 1 0 877645057 2662400 301 1283457024 134512640 135304128 4292259728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4898/statm: 650 301 253 194 0 36 0
[pid=4910] ppid=4898 vsize=26532 CPUtime=6.27
/proc/4910/stat : 4910 (clasp) R 4898 4898 4159 34819 4229 4202496 7032 0 19 0 622 5 0 0 25 0 1 0 877645062 27168768 6124 1283457024 134512640 136223643 4289318016 18446744073709551615 134930997 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4910/statm: 6633 6124 225 418 0 6213 0
Current children cumulated CPU time (s) 7.77
Current children cumulated vsize (KiB) 29132

[startup+8.81094 s]
/proc/loadavg: 1.14 1.04 0.79 2/45 4912
/proc/meminfo: memFree=856440/1048576 swapFree=2084088/2097144
[pid=4898] ppid=4897 vsize=2600 CPUtime=1.5
/proc/4898/stat : 4898 (aspcud-trendy-1) S 4897 4898 4159 34819 4229 4202496 619 18318 0 40 0 0 146 4 15 0 1 0 877645057 2662400 301 1283457024 134512640 135304128 4292259728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4898/statm: 650 301 253 194 0 36 0
[pid=4910] ppid=4898 vsize=27984 CPUtime=7.06
/proc/4910/stat : 4910 (clasp) R 4898 4898 4159 34819 4229 4202496 7376 0 19 0 700 6 0 0 25 0 1 0 877645062 28655616 6468 1283457024 134512640 136223643 4289318016 18446744073709551615 134704872 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4910/statm: 6996 6468 225 418 0 6576 0
Current children cumulated CPU time (s) 8.56
Current children cumulated vsize (KiB) 30584

[startup+9.01038 s]
/proc/loadavg: 1.14 1.04 0.79 2/45 4912
/proc/meminfo: memFree=856440/1048576 swapFree=2084088/2097144
[pid=4898] ppid=4897 vsize=2600 CPUtime=8.77
/proc/4898/stat : 4898 (aspcud-trendy-1) D 4897 4898 4159 34819 4229 4202496 619 26000 0 59 0 0 865 12 15 0 1 0 877645057 2662400 301 1283457024 134512640 135304128 4292259728 18446744073709551615 4294960130 0 0 16902 1132543225 18446744071564252162 0 0 17 0 0 0 0
/proc/4898/statm: 650 301 253 194 0 36 0
Current children cumulated CPU time (s) 8.77
Current children cumulated vsize (KiB) 2600

Child status: 0
Real time (s): 9.0478
CPU time (s): 8.80855
CPU user time (s): 8.67254
CPU system time (s): 0.136008
CPU usage (%): 97.3557
Max. virtual memory (cumulated for all children) (KiB): 48092

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 8.67254
system time used= 0.136008
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 30222
page faults= 61
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1149
involuntary context switches= 1104

runsolver used 0 second user time and 0 second system time

The end