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/201108241238/aspcud-trendy-1.5/rand399.cudf.dudf-random.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/dudf-random//rand399.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand399.cudf.dudf-random.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.04 1.03 1.00 5/36 10930
/proc/meminfo: memFree=609628/1048576 swapFree=0/0
[pid=10927] ppid=10926 vsize=2592 CPUtime=0
/proc/10927/stat : 10927 (aspcud-trendy-1) S 10926 10927 1511 34817 1511 4202496 375 0 0 0 0 0 0 0 18 0 1 0 2571425 2654208 280 1283457024 134512640 135304128 4291528416 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/10927/statm: 648 280 234 194 0 35 0
[pid=10928] ppid=10927 vsize=2592 CPUtime=0
/proc/10928/stat : 10928 (aspcud-trendy-1) S 10927 10927 1511 34817 1511 4202560 119 0 0 0 0 0 0 0 18 0 1 0 2571425 2654208 134 1283457024 134512640 135304128 4291528416 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/10928/statm: 648 134 87 194 0 35 0
[pid=10929] ppid=10928 vsize=2592 CPUtime=0
/proc/10929/stat : 10929 (aspcud-trendy-1) R 10928 10927 1511 34817 1511 4202560 127 0 0 0 0 0 0 0 25 0 1 0 2571425 2654208 151 1283457024 134512640 135304128 4291528416 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/10929/statm: 648 151 104 194 0 35 0
[pid=10930] ppid=10929 vsize=2592 CPUtime=0
/proc/10930/stat : 10930 (aspcud-trendy-1) R 10929 10927 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 2571426 2654208 47 1283457024 134512640 135304128 4291528416 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/10930/statm: 648 47 0 194 0 35 0

[startup+0.175671 s]
/proc/loadavg: 1.04 1.03 1.00 5/36 10930
/proc/meminfo: memFree=609628/1048576 swapFree=0/0
[pid=10927] ppid=10926 vsize=2600 CPUtime=0.01
/proc/10927/stat : 10927 (aspcud-trendy-1) S 10926 10927 1511 34817 1511 4202496 625 2229 0 0 0 0 0 1 25 0 1 0 2571425 2662400 299 1283457024 134512640 135304128 4291528416 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10927/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+0.205671 s]
/proc/loadavg: 1.04 1.03 1.00 5/36 10930
/proc/meminfo: memFree=609628/1048576 swapFree=0/0
[pid=10927] ppid=10926 vsize=2600 CPUtime=0.01
/proc/10927/stat : 10927 (aspcud-trendy-1) S 10926 10927 1511 34817 1511 4202496 625 2229 0 0 0 0 0 1 25 0 1 0 2571425 2662400 299 1283457024 134512640 135304128 4291528416 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10927/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+0.305698 s]
/proc/loadavg: 1.04 1.03 1.00 5/36 10930
/proc/meminfo: memFree=609628/1048576 swapFree=0/0
[pid=10927] ppid=10926 vsize=2600 CPUtime=0.01
/proc/10927/stat : 10927 (aspcud-trendy-1) S 10926 10927 1511 34817 1511 4202496 625 2229 0 0 0 0 0 1 25 0 1 0 2571425 2662400 299 1283457024 134512640 135304128 4291528416 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10927/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+0.705775 s]
/proc/loadavg: 1.04 1.03 1.00 5/36 10930
/proc/meminfo: memFree=609628/1048576 swapFree=0/0
[pid=10927] ppid=10926 vsize=2600 CPUtime=0.01
/proc/10927/stat : 10927 (aspcud-trendy-1) S 10926 10927 1511 34817 1511 4202496 625 2229 0 0 0 0 0 1 25 0 1 0 2571425 2662400 299 1283457024 134512640 135304128 4291528416 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10927/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+1.50594 s]
/proc/loadavg: 1.04 1.03 1.00 2/37 10941
/proc/meminfo: memFree=588900/1048576 swapFree=0/0
[pid=10927] ppid=10926 vsize=2600 CPUtime=1.29
/proc/10927/stat : 10927 (aspcud-trendy-1) S 10926 10927 1511 34817 1511 4202496 626 10458 0 0 0 0 123 6 18 0 1 0 2571425 2662400 299 1283457024 134512640 135304128 4291528416 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10927/statm: 650 299 251 194 0 37 0
[pid=10939] ppid=10927 vsize=6364 CPUtime=0.04
/proc/10939/stat : 10939 (clasp) R 10927 10927 1511 34817 1511 4202496 1493 0 0 0 4 0 0 0 18 0 1 0 2571427 6516736 1278 1283457024 134512640 136285277 4291141184 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/10939/statm: 1591 1278 177 433 0 1156 0
[pid=10940] ppid=10927 vsize=8876 CPUtime=0.16
/proc/10940/stat : 10940 (gringo) R 10927 10927 1511 34817 1511 4202496 2158 0 0 0 16 0 0 0 18 0 1 0 2571427 9089024 1749 1283457024 134512640 136933539 4289080512 18446744073709551615 134661328 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/10940/statm: 2219 1749 253 592 0 1624 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 17840

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

[startup+1.60595 s]
/proc/loadavg: 1.04 1.03 1.00 2/37 10941
/proc/meminfo: memFree=588900/1048576 swapFree=0/0
[pid=10927] ppid=10926 vsize=2600 CPUtime=1.29
/proc/10927/stat : 10927 (aspcud-trendy-1) S 10926 10927 1511 34817 1511 4202496 626 10458 0 0 0 0 123 6 18 0 1 0 2571425 2662400 299 1283457024 134512640 135304128 4291528416 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10927/statm: 650 299 251 194 0 37 0
[pid=10939] ppid=10927 vsize=9280 CPUtime=0.04
/proc/10939/stat : 10939 (clasp) R 10927 10927 1511 34817 1511 4202496 2341 0 0 0 4 0 0 0 18 0 1 0 2571427 9502720 2004 1283457024 134512640 136285277 4291141184 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/10939/statm: 2320 2004 177 433 0 1885 0
[pid=10940] ppid=10927 vsize=13440 CPUtime=0.26
/proc/10940/stat : 10940 (gringo) R 10927 10927 1511 34817 1511 4202496 3349 0 0 0 26 0 0 0 18 0 1 0 2571427 13762560 2683 1283457024 134512640 136933539 4289080512 18446744073709551615 136158960 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/10940/statm: 3360 2683 253 592 0 2765 0
Current children cumulated CPU time (s) 1.59
Current children cumulated vsize (KiB) 25320

[startup+2.00604 s]
/proc/loadavg: 1.04 1.03 1.00 2/37 10941
/proc/meminfo: memFree=588900/1048576 swapFree=0/0
[pid=10927] ppid=10926 vsize=2600 CPUtime=1.71
/proc/10927/stat : 10927 (aspcud-trendy-1) S 10926 10927 1511 34817 1511 4202496 626 15333 0 0 0 0 164 7 16 0 1 0 2571425 2662400 299 1283457024 134512640 135304128 4291528416 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10927/statm: 650 299 251 194 0 37 0
[pid=10939] ppid=10927 vsize=15108 CPUtime=0.28
/proc/10939/stat : 10939 (clasp) R 10927 10927 1511 34817 1511 4202496 4284 0 0 0 26 2 0 0 18 0 1 0 2571427 15470592 3526 1283457024 134512640 136285277 4291141184 18446744073709551615 134669387 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/10939/statm: 3777 3526 234 433 0 3342 0
Current children cumulated CPU time (s) 1.99
Current children cumulated vsize (KiB) 17708

[startup+2.10605 s]
/proc/loadavg: 1.04 1.03 1.00 2/37 10941
/proc/meminfo: memFree=588900/1048576 swapFree=0/0
[pid=10927] ppid=10926 vsize=2600 CPUtime=1.71
/proc/10927/stat : 10927 (aspcud-trendy-1) S 10926 10927 1511 34817 1511 4202496 626 15333 0 0 0 0 164 7 16 0 1 0 2571425 2662400 299 1283457024 134512640 135304128 4291528416 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/10927/statm: 650 299 251 194 0 37 0
[pid=10939] ppid=10927 vsize=15108 CPUtime=0.38
/proc/10939/stat : 10939 (clasp) R 10927 10927 1511 34817 1511 4202496 4284 0 0 0 36 2 0 0 18 0 1 0 2571427 15470592 3526 1283457024 134512640 136285277 4291141184 18446744073709551615 134931883 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/10939/statm: 3777 3526 234 433 0 3342 0
Current children cumulated CPU time (s) 2.09
Current children cumulated vsize (KiB) 17708

Child status: 0
Real time (s): 2.2028
CPU time (s): 2.20014
CPU user time (s): 2.08813
CPU system time (s): 0.112007
CPU usage (%): 99.8793
Max. virtual memory (cumulated for all children) (KiB): 38644

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 2.08813
system time used= 0.112007
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 24004
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= 488
involuntary context switches= 358

runsolver used 0 second user time and 0 second system time

The end