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/rand440.cudf.dudf-random.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/dudf-random//rand440.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand440.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.14 1.10 1.03 5/35 14635
/proc/meminfo: memFree=428764/1048576 swapFree=0/0
[pid=14633] ppid=14632 vsize=2588 CPUtime=0
/proc/14633/stat : 14633 (aspcud-trendy-1) S 14632 14633 1511 34817 1511 4202496 372 0 0 0 0 0 0 0 18 0 1 0 3332378 2650112 279 1283457024 134512640 135304128 4289023104 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/14633/statm: 647 279 234 194 0 34 0
[pid=14634] ppid=14633 vsize=2588 CPUtime=0
/proc/14634/stat : 14634 (aspcud-trendy-1) R 14633 14633 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 3332378 2650112 132 1283457024 134512640 135304128 4289023104 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/14634/statm: 647 132 86 194 0 34 0
[pid=14635] ppid=14634 vsize=2588 CPUtime=0
/proc/14635/stat : 14635 (aspcud-trendy-1) R 14634 14633 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 3332378 2650112 46 1283457024 134512640 135304128 4289023104 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/14635/statm: 647 46 0 194 0 34 0

[startup+0.125256 s]
/proc/loadavg: 1.14 1.10 1.03 5/35 14635
/proc/meminfo: memFree=428764/1048576 swapFree=0/0
[pid=14633] ppid=14632 vsize=2596 CPUtime=0.01
/proc/14633/stat : 14633 (aspcud-trendy-1) S 14632 14633 1511 34817 1511 4202496 621 2234 0 0 0 0 0 1 25 0 1 0 3332378 2658304 298 1283457024 134512640 135304128 4289023104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14633/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.205273 s]
/proc/loadavg: 1.14 1.10 1.03 5/35 14635
/proc/meminfo: memFree=428764/1048576 swapFree=0/0
[pid=14633] ppid=14632 vsize=2596 CPUtime=0.01
/proc/14633/stat : 14633 (aspcud-trendy-1) S 14632 14633 1511 34817 1511 4202496 621 2234 0 0 0 0 0 1 25 0 1 0 3332378 2658304 298 1283457024 134512640 135304128 4289023104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14633/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.305297 s]
/proc/loadavg: 1.14 1.10 1.03 5/35 14635
/proc/meminfo: memFree=428764/1048576 swapFree=0/0
[pid=14633] ppid=14632 vsize=2596 CPUtime=0.01
/proc/14633/stat : 14633 (aspcud-trendy-1) S 14632 14633 1511 34817 1511 4202496 621 2234 0 0 0 0 0 1 25 0 1 0 3332378 2658304 298 1283457024 134512640 135304128 4289023104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14633/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.705374 s]
/proc/loadavg: 1.14 1.10 1.03 5/35 14635
/proc/meminfo: memFree=428764/1048576 swapFree=0/0
[pid=14633] ppid=14632 vsize=2596 CPUtime=0.01
/proc/14633/stat : 14633 (aspcud-trendy-1) S 14632 14633 1511 34817 1511 4202496 621 2234 0 0 0 0 0 1 25 0 1 0 3332378 2658304 298 1283457024 134512640 135304128 4289023104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14633/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+1.50554 s]
/proc/loadavg: 1.14 1.10 1.03 2/37 14647
/proc/meminfo: memFree=406780/1048576 swapFree=0/0
[pid=14633] ppid=14632 vsize=2596 CPUtime=0.01
/proc/14633/stat : 14633 (aspcud-trendy-1) S 14632 14633 1511 34817 1511 4202496 621 2234 0 0 0 0 0 1 25 0 1 0 3332378 2658304 298 1283457024 134512640 135304128 4289023104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14633/statm: 649 298 251 194 0 36 0
[pid=14645] ppid=14633 vsize=1928 CPUtime=0
/proc/14645/stat : 14645 (clasp) S 14633 14633 1511 34817 1511 4202496 291 0 0 0 0 0 0 0 25 0 1 0 3332379 1974272 159 1283457024 134512640 136285277 4288162672 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/14645/statm: 482 159 144 433 0 47 0
[pid=14646] ppid=14633 vsize=2584 CPUtime=0
/proc/14646/stat : 14646 (gringo) S 14633 14633 1511 34817 1511 4202496 404 0 0 0 0 0 0 0 25 0 1 0 3332379 2646016 272 1283457024 134512640 136933539 4292190144 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/14646/statm: 646 272 242 592 0 51 0
[pid=14647] ppid=14633 vsize=25004 CPUtime=1.49
/proc/14647/stat : 14647 (cudf2lp) R 14633 14633 1511 34817 1511 4202496 7229 0 0 0 145 4 0 0 25 0 1 0 3332379 25604096 5631 1283457024 134512640 135786343 4292661328 18446744073709551615 135052167 0 0 6 0 0 0 0 17 0 0 0 0
/proc/14647/statm: 6251 5631 126 311 0 5938 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 32112

[startup+3.10588 s]
/proc/loadavg: 1.14 1.10 1.03 3/37 14647
/proc/meminfo: memFree=387560/1048576 swapFree=0/0
[pid=14633] ppid=14632 vsize=2596 CPUtime=2.35
/proc/14633/stat : 14633 (aspcud-trendy-1) S 14632 14633 1511 34817 1511 4202496 623 15140 0 0 0 0 228 7 18 0 1 0 3332378 2658304 298 1283457024 134512640 135304128 4289023104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14633/statm: 649 298 251 194 0 36 0
[pid=14645] ppid=14633 vsize=15604 CPUtime=0.04
/proc/14645/stat : 14645 (clasp) R 14633 14633 1511 34817 1511 4202496 4289 0 0 0 4 0 0 0 18 0 1 0 3332379 15978496 3499 1283457024 134512640 136285277 4288162672 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/14645/statm: 3901 3499 177 433 0 3466 0
[pid=14646] ppid=14633 vsize=25656 CPUtime=0.69
/proc/14646/stat : 14646 (gringo) R 14633 14633 1511 34817 1511 4202496 7143 0 0 0 66 3 0 0 18 0 1 0 3332379 26271744 4967 1283457024 134512640 136933539 4292190144 18446744073709551615 136204821 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14646/statm: 6414 4967 253 592 0 5819 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 43856

[startup+6.30687 s]
/proc/loadavg: 1.20 1.12 1.03 2/35 14647
/proc/meminfo: memFree=391444/1048576 swapFree=0/0
[pid=14633] ppid=14632 vsize=2596 CPUtime=3.74
/proc/14633/stat : 14633 (aspcud-trendy-1) S 14632 14633 1511 34817 1511 4202496 623 29187 0 0 0 0 359 15 18 0 1 0 3332378 2658304 298 1283457024 134512640 135304128 4289023104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14633/statm: 649 298 251 194 0 36 0
[pid=14645] ppid=14633 vsize=38680 CPUtime=2.55
/proc/14645/stat : 14645 (clasp) R 14633 14633 1511 34817 1511 4202496 11556 0 0 0 251 4 0 0 22 0 1 0 3332379 39608320 9409 1283457024 134512640 136285277 4288162672 18446744073709551615 134686290 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/14645/statm: 9670 9409 234 433 0 9235 0
Current children cumulated CPU time (s) 6.29
Current children cumulated vsize (KiB) 41276

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

[startup+6.4069 s]
/proc/loadavg: 1.20 1.12 1.03 2/35 14647
/proc/meminfo: memFree=391444/1048576 swapFree=0/0
[pid=14633] ppid=14632 vsize=2596 CPUtime=3.74
/proc/14633/stat : 14633 (aspcud-trendy-1) S 14632 14633 1511 34817 1511 4202496 623 29187 0 0 0 0 359 15 18 0 1 0 3332378 2658304 298 1283457024 134512640 135304128 4289023104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14633/statm: 649 298 251 194 0 36 0
[pid=14645] ppid=14633 vsize=38680 CPUtime=2.65
/proc/14645/stat : 14645 (clasp) R 14633 14633 1511 34817 1511 4202496 11556 0 0 0 261 4 0 0 22 0 1 0 3332379 39608320 9409 1283457024 134512640 136285277 4288162672 18446744073709551615 134930675 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/14645/statm: 9670 9409 234 433 0 9235 0
Current children cumulated CPU time (s) 6.39
Current children cumulated vsize (KiB) 41276

[startup+6.80701 s]
/proc/loadavg: 1.20 1.12 1.03 2/35 14647
/proc/meminfo: memFree=391444/1048576 swapFree=0/0
[pid=14633] ppid=14632 vsize=2596 CPUtime=3.74
/proc/14633/stat : 14633 (aspcud-trendy-1) S 14632 14633 1511 34817 1511 4202496 623 29187 0 0 0 0 359 15 18 0 1 0 3332378 2658304 298 1283457024 134512640 135304128 4289023104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14633/statm: 649 298 251 194 0 36 0
[pid=14645] ppid=14633 vsize=38680 CPUtime=3.05
/proc/14645/stat : 14645 (clasp) R 14633 14633 1511 34817 1511 4202496 11556 0 0 0 301 4 0 0 24 0 1 0 3332379 39608320 9409 1283457024 134512640 136285277 4288162672 18446744073709551615 134893169 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/14645/statm: 9670 9409 234 433 0 9235 0
Current children cumulated CPU time (s) 6.79
Current children cumulated vsize (KiB) 41276

Child status: 0
Real time (s): 6.90115
CPU time (s): 6.89243
CPU user time (s): 6.66842
CPU system time (s): 0.224014
CPU usage (%): 99.8737
Max. virtual memory (cumulated for all children) (KiB): 84440

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 6.66842
system time used= 0.224014
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 45337
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= 1592
involuntary context switches= 1225

runsolver used 0 second user time and 0 second system time

The end