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/2c3aece6-c8b2-11df-a040-00163e3d3b7c.cudf.dudf-real.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/dudf-real//2c3aece6-c8b2-11df-a040-00163e3d3b7c.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/2c3aece6-c8b2-11df-a040-00163e3d3b7c.cudf.dudf-real.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.18 1.14 1.05 5/37 14862
/proc/meminfo: memFree=406544/1048576 swapFree=0/0
[pid=14860] ppid=14859 vsize=2584 CPUtime=0
/proc/14860/stat : 14860 (aspcud-trendy-1) S 14859 14860 1511 34817 1511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 3341970 2646016 279 1283457024 134512640 135304128 4287617776 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/14860/statm: 646 279 234 194 0 33 0
[pid=14861] ppid=14860 vsize=2584 CPUtime=0
/proc/14861/stat : 14861 (aspcud-trendy-1) R 14860 14860 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 3341970 2646016 132 1283457024 134512640 135304128 4287617776 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/14861/statm: 646 132 86 194 0 33 0
[pid=14862] ppid=14861 vsize=2584 CPUtime=0
/proc/14862/stat : 14862 (aspcud-trendy-1) R 14861 14860 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 3341970 2646016 46 1283457024 134512640 135304128 4287617776 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/14862/statm: 646 46 0 194 0 33 0

[startup+0.125375 s]
/proc/loadavg: 1.18 1.14 1.05 5/37 14862
/proc/meminfo: memFree=406544/1048576 swapFree=0/0
[pid=14860] ppid=14859 vsize=2592 CPUtime=0.01
/proc/14860/stat : 14860 (aspcud-trendy-1) S 14859 14860 1511 34817 1511 4202496 623 2231 0 0 0 0 1 0 25 0 1 0 3341970 2654208 298 1283457024 134512640 135304128 4287617776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14860/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.20538 s]
/proc/loadavg: 1.18 1.14 1.05 5/37 14862
/proc/meminfo: memFree=406544/1048576 swapFree=0/0
[pid=14860] ppid=14859 vsize=2592 CPUtime=0.01
/proc/14860/stat : 14860 (aspcud-trendy-1) S 14859 14860 1511 34817 1511 4202496 623 2231 0 0 0 0 1 0 25 0 1 0 3341970 2654208 298 1283457024 134512640 135304128 4287617776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14860/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.305401 s]
/proc/loadavg: 1.18 1.14 1.05 5/37 14862
/proc/meminfo: memFree=406544/1048576 swapFree=0/0
[pid=14860] ppid=14859 vsize=2592 CPUtime=0.01
/proc/14860/stat : 14860 (aspcud-trendy-1) S 14859 14860 1511 34817 1511 4202496 623 2231 0 0 0 0 1 0 25 0 1 0 3341970 2654208 298 1283457024 134512640 135304128 4287617776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14860/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.705461 s]
/proc/loadavg: 1.18 1.14 1.05 5/37 14862
/proc/meminfo: memFree=406544/1048576 swapFree=0/0
[pid=14860] ppid=14859 vsize=2592 CPUtime=0.01
/proc/14860/stat : 14860 (aspcud-trendy-1) S 14859 14860 1511 34817 1511 4202496 623 2231 0 0 0 0 1 0 25 0 1 0 3341970 2654208 298 1283457024 134512640 135304128 4287617776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14860/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+1.50563 s]
/proc/loadavg: 1.18 1.14 1.05 2/39 14875
/proc/meminfo: memFree=383940/1048576 swapFree=0/0
[pid=14860] ppid=14859 vsize=2592 CPUtime=0.01
/proc/14860/stat : 14860 (aspcud-trendy-1) S 14859 14860 1511 34817 1511 4202496 623 2231 0 0 0 0 1 0 25 0 1 0 3341970 2654208 298 1283457024 134512640 135304128 4287617776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14860/statm: 648 298 251 194 0 35 0
[pid=14872] ppid=14860 vsize=1928 CPUtime=0
/proc/14872/stat : 14872 (clasp) S 14860 14860 1511 34817 1511 4202496 292 0 0 0 0 0 0 0 25 0 1 0 3341972 1974272 160 1283457024 134512640 136285277 4292868064 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/14872/statm: 482 160 144 433 0 47 0
[pid=14873] ppid=14860 vsize=2584 CPUtime=0
/proc/14873/stat : 14873 (gringo) S 14860 14860 1511 34817 1511 4202496 404 0 0 0 0 0 0 0 25 0 1 0 3341972 2646016 272 1283457024 134512640 136933539 4288857232 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/14873/statm: 646 272 242 592 0 51 0
[pid=14874] ppid=14860 vsize=39228 CPUtime=1.5
/proc/14874/stat : 14874 (cudf2lp) R 14860 14860 1511 34817 1511 4202496 10939 0 0 0 146 4 0 0 25 0 1 0 3341972 40169472 9292 1283457024 134512640 135786343 4289947056 18446744073709551615 135200584 0 0 6 0 0 0 0 17 0 0 0 0
/proc/14874/statm: 9807 9292 133 311 0 9494 0
Current children cumulated CPU time (s) 1.51
Current children cumulated vsize (KiB) 46332

[startup+3.10597 s]
/proc/loadavg: 1.18 1.14 1.05 4/39 14875
/proc/meminfo: memFree=389156/1048576 swapFree=0/0
[pid=14860] ppid=14859 vsize=2592 CPUtime=2.78
/proc/14860/stat : 14860 (aspcud-trendy-1) S 14859 14860 1511 34817 1511 4202496 624 24149 0 0 0 0 267 11 15 0 1 0 3341970 2654208 298 1283457024 134512640 135304128 4287617776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14860/statm: 648 298 251 194 0 35 0
[pid=14872] ppid=14860 vsize=29432 CPUtime=0.32
/proc/14872/stat : 14872 (clasp) R 14860 14860 1511 34817 1511 4202496 7913 0 0 0 30 2 0 0 18 0 1 0 3341972 30138368 6920 1283457024 134512640 136285277 4292868064 18446744073709551615 135054647 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/14872/statm: 7358 6920 189 433 0 6923 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 32024

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

[startup+3.20599 s]
/proc/loadavg: 1.18 1.14 1.05 4/39 14875
/proc/meminfo: memFree=389156/1048576 swapFree=0/0
[pid=14860] ppid=14859 vsize=2592 CPUtime=2.78
/proc/14860/stat : 14860 (aspcud-trendy-1) S 14859 14860 1511 34817 1511 4202496 624 24149 0 0 0 0 267 11 15 0 1 0 3341970 2654208 298 1283457024 134512640 135304128 4287617776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14860/statm: 648 298 251 194 0 35 0
[pid=14872] ppid=14860 vsize=33176 CPUtime=0.42
/proc/14872/stat : 14872 (clasp) R 14860 14860 1511 34817 1511 4202496 9470 0 0 0 39 3 0 0 18 0 1 0 3341972 33972224 7926 1283457024 134512640 136285277 4292868064 18446744073709551615 135631709 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/14872/statm: 8294 7926 208 433 0 7859 0
Current children cumulated CPU time (s) 3.2
Current children cumulated vsize (KiB) 35768

[startup+3.60609 s]
/proc/loadavg: 1.25 1.15 1.05 2/37 14875
/proc/meminfo: memFree=375788/1048576 swapFree=0/0
[pid=14860] ppid=14859 vsize=2592 CPUtime=2.78
/proc/14860/stat : 14860 (aspcud-trendy-1) S 14859 14860 1511 34817 1511 4202496 624 24149 0 0 0 0 267 11 15 0 1 0 3341970 2654208 298 1283457024 134512640 135304128 4287617776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14860/statm: 648 298 251 194 0 35 0
[pid=14872] ppid=14860 vsize=31960 CPUtime=0.82
/proc/14872/stat : 14872 (clasp) R 14860 14860 1511 34817 1511 4202496 9510 0 0 0 78 4 0 0 18 0 1 0 3341972 32727040 7750 1283457024 134512640 136285277 4292868064 18446744073709551615 134669568 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/14872/statm: 7990 7750 234 433 0 7555 0
Current children cumulated CPU time (s) 3.6
Current children cumulated vsize (KiB) 34552

[startup+3.80613 s]
/proc/loadavg: 1.25 1.15 1.05 2/37 14875
/proc/meminfo: memFree=375788/1048576 swapFree=0/0
[pid=14860] ppid=14859 vsize=2592 CPUtime=2.78
/proc/14860/stat : 14860 (aspcud-trendy-1) S 14859 14860 1511 34817 1511 4202496 624 24149 0 0 0 0 267 11 15 0 1 0 3341970 2654208 298 1283457024 134512640 135304128 4287617776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14860/statm: 648 298 251 194 0 35 0
[pid=14872] ppid=14860 vsize=31960 CPUtime=1.02
/proc/14872/stat : 14872 (clasp) R 14860 14860 1511 34817 1511 4202496 9510 0 0 0 98 4 0 0 19 0 1 0 3341972 32727040 7750 1283457024 134512640 136285277 4292868064 18446744073709551615 134893055 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/14872/statm: 7990 7750 234 433 0 7555 0
Current children cumulated CPU time (s) 3.8
Current children cumulated vsize (KiB) 34552

[startup+3.90615 s]
/proc/loadavg: 1.25 1.15 1.05 2/37 14875
/proc/meminfo: memFree=375788/1048576 swapFree=0/0
[pid=14860] ppid=14859 vsize=2980 CPUtime=3.89
/proc/14860/stat : 14860 (aspcud-trendy-1) R 14859 14860 1511 34817 1511 4202496 921 35491 0 0 0 0 372 17 18 0 1 0 3341970 3051520 378 1283457024 134512640 135304128 4287617776 18446744073709551615 4294960130 0 65538 16902 1132543225 0 0 0 17 0 0 0 0
/proc/14860/statm: 745 378 256 194 0 132 0
Current children cumulated CPU time (s) 3.89
Current children cumulated vsize (KiB) 2980

Child status: 0
Real time (s): 3.91704
CPU time (s): 3.92025
CPU user time (s): 3.72823
CPU system time (s): 0.192012
CPU usage (%): 100.082
Max. virtual memory (cumulated for all children) (KiB): 66612

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 3.72823
system time used= 0.192012
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 38267
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= 1221
involuntary context switches= 888

runsolver used 0 second user time and 0 second system time

The end