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/201109011757/aspcud-1.5/rand83.cudf.dudf-random.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-random//rand83.cudf /home/misc2010/tmp/201109011757/aspcud-1.5/rand83.cudf.dudf-random.result -sum(pin-priority-1),-sum(pin-priority-500),-sum(pin-priority-700),-notuptodate,-removed,-changed 

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.34 1.11 1.03 5/35 30026
/proc/meminfo: memFree=608948/1048576 swapFree=0/0
[pid=30024] ppid=30023 vsize=2584 CPUtime=0
/proc/30024/stat : 30024 (aspcud-1.5) S 30023 30024 22717 34817 22717 4202496 372 0 0 0 0 0 0 0 21 0 1 0 72687705 2646016 279 1283457024 134512640 135304128 4292624272 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/30024/statm: 646 279 234 194 0 33 0
[pid=30025] ppid=30024 vsize=2584 CPUtime=0
/proc/30025/stat : 30025 (aspcud-1.5) R 30024 30024 22717 34817 22717 4202560 110 0 0 0 0 0 0 0 25 0 1 0 72687706 2646016 132 1283457024 134512640 135304128 4292624272 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/30025/statm: 646 132 86 194 0 33 0
[pid=30026] ppid=30025 vsize=2584 CPUtime=0
/proc/30026/stat : 30026 (aspcud-1.5) R 30025 30024 22717 34817 22717 4202560 0 0 0 0 0 0 0 0 25 0 1 0 72687706 2646016 46 1283457024 134512640 135304128 4292624272 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/30026/statm: 646 46 0 194 0 33 0

[startup+0.163512 s]
/proc/loadavg: 1.34 1.11 1.03 5/35 30026
/proc/meminfo: memFree=608948/1048576 swapFree=0/0
[pid=30024] ppid=30023 vsize=2592 CPUtime=0
/proc/30024/stat : 30024 (aspcud-1.5) S 30023 30024 22717 34817 22717 4202496 575 1522 0 0 0 0 0 0 25 0 1 0 72687705 2654208 298 1283457024 134512640 135304128 4292624272 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/30024/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.207486 s]
/proc/loadavg: 1.34 1.11 1.03 5/35 30026
/proc/meminfo: memFree=608948/1048576 swapFree=0/0
[pid=30024] ppid=30023 vsize=2592 CPUtime=0
/proc/30024/stat : 30024 (aspcud-1.5) S 30023 30024 22717 34817 22717 4202496 575 1522 0 0 0 0 0 0 25 0 1 0 72687705 2654208 298 1283457024 134512640 135304128 4292624272 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/30024/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.307516 s]
/proc/loadavg: 1.34 1.11 1.03 5/35 30026
/proc/meminfo: memFree=608948/1048576 swapFree=0/0
[pid=30024] ppid=30023 vsize=2592 CPUtime=0
/proc/30024/stat : 30024 (aspcud-1.5) S 30023 30024 22717 34817 22717 4202496 575 1522 0 0 0 0 0 0 25 0 1 0 72687705 2654208 298 1283457024 134512640 135304128 4292624272 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/30024/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.703537 s]
/proc/loadavg: 1.34 1.11 1.03 5/35 30026
/proc/meminfo: memFree=608948/1048576 swapFree=0/0
[pid=30024] ppid=30023 vsize=2592 CPUtime=0
/proc/30024/stat : 30024 (aspcud-1.5) S 30023 30024 22717 34817 22717 4202496 575 1522 0 0 0 0 0 0 25 0 1 0 72687705 2654208 298 1283457024 134512640 135304128 4292624272 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/30024/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.5131 s]
/proc/loadavg: 1.34 1.11 1.03 2/37 30035
/proc/meminfo: memFree=576812/1048576 swapFree=0/0
[pid=30024] ppid=30023 vsize=2592 CPUtime=0
/proc/30024/stat : 30024 (aspcud-1.5) S 30023 30024 22717 34817 22717 4202496 575 1522 0 0 0 0 0 0 25 0 1 0 72687705 2654208 298 1283457024 134512640 135304128 4292624272 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/30024/statm: 648 298 251 194 0 35 0
[pid=30033] ppid=30024 vsize=1932 CPUtime=0
/proc/30033/stat : 30033 (clasp) S 30024 30024 22717 34817 22717 4202496 292 0 0 0 0 0 0 0 25 0 1 0 72687707 1978368 160 1283457024 134512640 136285277 4292130624 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/30033/statm: 483 160 144 433 0 48 0
[pid=30034] ppid=30024 vsize=2588 CPUtime=0
/proc/30034/stat : 30034 (gringo) S 30024 30024 22717 34817 22717 4202496 404 0 0 0 0 0 0 0 25 0 1 0 72687707 2650112 272 1283457024 134512640 136933539 4286579312 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/30034/statm: 647 272 242 592 0 52 0
[pid=30035] ppid=30024 vsize=29448 CPUtime=1.26
/proc/30035/stat : 30035 (cudf2lp) D 30024 30024 22717 34817 22717 4202496 8156 0 0 0 124 2 0 0 25 0 1 0 72687707 30154752 6655 1283457024 134512640 135786343 4293269648 18446744073709551615 135258478 0 0 6 0 18446744071564332000 0 0 17 0 0 0 0
/proc/30035/statm: 7362 6655 128 311 0 7049 0
Current children cumulated CPU time (s) 1.26
Current children cumulated vsize (KiB) 36560

[startup+3.10643 s]
/proc/loadavg: 1.34 1.11 1.03 2/37 30035
/proc/meminfo: memFree=535444/1048576 swapFree=0/0
[pid=30024] ppid=30023 vsize=2592 CPUtime=0
/proc/30024/stat : 30024 (aspcud-1.5) S 30023 30024 22717 34817 22717 4202496 575 1522 0 0 0 0 0 0 25 0 1 0 72687705 2654208 298 1283457024 134512640 135304128 4292624272 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/30024/statm: 648 298 251 194 0 35 0
[pid=30033] ppid=30024 vsize=11496 CPUtime=0.04
/proc/30033/stat : 30033 (clasp) S 30024 30024 22717 34817 22717 4202496 3064 0 0 0 3 1 0 0 18 0 1 0 72687707 11771904 2546 1283457024 134512640 136285277 4292130624 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/30033/statm: 2874 2546 177 433 0 2439 0
[pid=30034] ppid=30024 vsize=15768 CPUtime=0.56
/proc/30034/stat : 30034 (gringo) S 30024 30024 22717 34817 22717 4202496 4516 0 0 0 55 1 0 0 18 0 1 0 72687707 16146432 2951 1283457024 134512640 136933539 4286579312 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/30034/statm: 3942 2951 242 592 0 3347 0
[pid=30035] ppid=30024 vsize=45688 CPUtime=2.19
/proc/30035/stat : 30035 (cudf2lp) R 30024 30024 22717 34817 22717 4202496 14083 0 0 0 216 3 0 0 25 0 1 0 72687707 46784512 11215 1283457024 134512640 135786343 4293269648 18446744073709551615 135191523 0 0 6 0 0 0 0 17 0 0 0 0
/proc/30035/statm: 11422 11215 139 311 0 11109 0
Current children cumulated CPU time (s) 2.79
Current children cumulated vsize (KiB) 75544

[startup+6.30739 s]
/proc/loadavg: 1.39 1.12 1.03 2/35 30035
/proc/meminfo: memFree=546520/1048576 swapFree=0/0
[pid=30024] ppid=30023 vsize=2592 CPUtime=3.6
/proc/30024/stat : 30024 (aspcud-1.5) S 30023 30024 22717 34817 22717 4202496 575 29173 0 0 0 0 348 12 18 0 1 0 72687705 2654208 298 1283457024 134512640 135304128 4292624272 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/30024/statm: 648 298 251 194 0 35 0
[pid=30033] ppid=30024 vsize=47920 CPUtime=2.39
/proc/30033/stat : 30033 (clasp) R 30024 30024 22717 34817 22717 4202496 13677 0 0 0 233 6 0 0 21 0 1 0 72687707 49070080 11755 1283457024 134512640 136285277 4292130624 18446744073709551615 134967001 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/30033/statm: 11980 11755 234 433 0 11545 0
Current children cumulated CPU time (s) 5.99
Current children cumulated vsize (KiB) 50512

[startup+12.7091 s]
/proc/loadavg: 1.36 1.12 1.03 2/35 30035
/proc/meminfo: memFree=435912/1048576 swapFree=0/0
[pid=30024] ppid=30023 vsize=2592 CPUtime=3.6
/proc/30024/stat : 30024 (aspcud-1.5) S 30023 30024 22717 34817 22717 4202496 575 29173 0 0 0 0 348 12 18 0 1 0 72687705 2654208 298 1283457024 134512640 135304128 4292624272 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/30024/statm: 648 298 251 194 0 35 0
[pid=30033] ppid=30024 vsize=146924 CPUtime=8.79
/proc/30033/stat : 30033 (clasp) R 30024 30024 22717 34817 22717 4202496 38418 0 0 0 865 14 0 0 25 0 1 0 72687707 150450176 36496 1283457024 134512640 136285277 4292130624 18446744073709551615 134964959 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/30033/statm: 36731 36496 234 433 0 36296 0
Current children cumulated CPU time (s) 12.39
Current children cumulated vsize (KiB) 149516

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

[startup+12.8091 s]
/proc/loadavg: 1.36 1.12 1.03 2/35 30035
/proc/meminfo: memFree=435912/1048576 swapFree=0/0
[pid=30024] ppid=30023 vsize=2592 CPUtime=3.6
/proc/30024/stat : 30024 (aspcud-1.5) S 30023 30024 22717 34817 22717 4202496 575 29173 0 0 0 0 348 12 18 0 1 0 72687705 2654208 298 1283457024 134512640 135304128 4292624272 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/30024/statm: 648 298 251 194 0 35 0
[pid=30033] ppid=30024 vsize=146924 CPUtime=8.89
/proc/30033/stat : 30033 (clasp) R 30024 30024 22717 34817 22717 4202496 38418 0 0 0 875 14 0 0 25 0 1 0 72687707 150450176 36496 1283457024 134512640 136285277 4292130624 18446744073709551615 134650604 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/30033/statm: 36731 36496 234 433 0 36296 0
Current children cumulated CPU time (s) 12.49
Current children cumulated vsize (KiB) 149516

[startup+19.2108 s]
/proc/loadavg: 1.30 1.12 1.03 2/35 30035
/proc/meminfo: memFree=427232/1048576 swapFree=0/0
[pid=30024] ppid=30023 vsize=2592 CPUtime=3.6
/proc/30024/stat : 30024 (aspcud-1.5) S 30023 30024 22717 34817 22717 4202496 575 29173 0 0 0 0 348 12 18 0 1 0 72687705 2654208 298 1283457024 134512640 135304128 4292624272 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/30024/statm: 648 298 251 194 0 35 0
[pid=30033] ppid=30024 vsize=155696 CPUtime=15.29
/proc/30033/stat : 30033 (clasp) R 30024 30024 22717 34817 22717 4202496 40627 0 0 0 1513 16 0 0 25 0 1 0 72687707 159432704 38705 1283457024 134512640 136285277 4292130624 18446744073709551615 134733705 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/30033/statm: 38924 38705 234 433 0 38489 0
Current children cumulated CPU time (s) 18.89
Current children cumulated vsize (KiB) 158288

[startup+22.4116 s]
/proc/loadavg: 1.30 1.12 1.03 2/35 30035
/proc/meminfo: memFree=427356/1048576 swapFree=0/0
[pid=30024] ppid=30023 vsize=2592 CPUtime=3.6
/proc/30024/stat : 30024 (aspcud-1.5) S 30023 30024 22717 34817 22717 4202496 575 29173 0 0 0 0 348 12 18 0 1 0 72687705 2654208 298 1283457024 134512640 135304128 4292624272 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/30024/statm: 648 298 251 194 0 35 0
[pid=30033] ppid=30024 vsize=154856 CPUtime=18.49
/proc/30033/stat : 30033 (clasp) R 30024 30024 22717 34817 22717 4202496 40627 0 0 0 1833 16 0 0 25 0 1 0 72687707 158572544 38498 1283457024 134512640 136285277 4292130624 18446744073709551615 134669574 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/30033/statm: 38714 38498 234 433 0 38279 0
Current children cumulated CPU time (s) 22.09
Current children cumulated vsize (KiB) 157448

[startup+23.2117 s]
/proc/loadavg: 1.30 1.12 1.03 2/35 30035
/proc/meminfo: memFree=427356/1048576 swapFree=0/0
[pid=30024] ppid=30023 vsize=2592 CPUtime=3.6
/proc/30024/stat : 30024 (aspcud-1.5) S 30023 30024 22717 34817 22717 4202496 575 29173 0 0 0 0 348 12 18 0 1 0 72687705 2654208 298 1283457024 134512640 135304128 4292624272 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/30024/statm: 648 298 251 194 0 35 0
[pid=30033] ppid=30024 vsize=154856 CPUtime=19.28
/proc/30033/stat : 30033 (clasp) R 30024 30024 22717 34817 22717 4202496 40627 0 0 0 1912 16 0 0 25 0 1 0 72687707 158572544 38498 1283457024 134512640 136285277 4292130624 18446744073709551615 134719465 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/30033/statm: 38714 38498 234 433 0 38279 0
Current children cumulated CPU time (s) 22.88
Current children cumulated vsize (KiB) 157448

[startup+23.6118 s]
/proc/loadavg: 1.30 1.12 1.03 2/35 30035
/proc/meminfo: memFree=427356/1048576 swapFree=0/0
[pid=30024] ppid=30023 vsize=2592 CPUtime=3.6
/proc/30024/stat : 30024 (aspcud-1.5) S 30023 30024 22717 34817 22717 4202496 575 29173 0 0 0 0 348 12 18 0 1 0 72687705 2654208 298 1283457024 134512640 135304128 4292624272 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/30024/statm: 648 298 251 194 0 35 0
[pid=30033] ppid=30024 vsize=154856 CPUtime=19.68
/proc/30033/stat : 30033 (clasp) R 30024 30024 22717 34817 22717 4202496 40627 0 0 0 1952 16 0 0 25 0 1 0 72687707 158572544 38498 1283457024 134512640 136285277 4292130624 18446744073709551615 134649474 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/30033/statm: 38714 38498 234 433 0 38279 0
Current children cumulated CPU time (s) 23.28
Current children cumulated vsize (KiB) 157448

[startup+23.8128 s]
/proc/loadavg: 1.30 1.12 1.03 2/35 30035
/proc/meminfo: memFree=427356/1048576 swapFree=0/0
[pid=30024] ppid=30023 vsize=2592 CPUtime=3.6
/proc/30024/stat : 30024 (aspcud-1.5) S 30023 30024 22717 34817 22717 4202496 575 29173 0 0 0 0 348 12 18 0 1 0 72687705 2654208 298 1283457024 134512640 135304128 4292624272 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/30024/statm: 648 298 251 194 0 35 0
[pid=30033] ppid=30024 vsize=26664 CPUtime=19.88
/proc/30033/stat : 30033 (clasp) R 30024 30024 22717 34817 22717 4202496 40635 0 0 0 1968 20 0 0 25 0 1 0 72687707 27303936 4421 1283457024 134512640 136285277 4292130624 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/30033/statm: 6666 4421 242 433 0 6231 0
Current children cumulated CPU time (s) 23.48
Current children cumulated vsize (KiB) 29256

Child status: 0
Real time (s): 23.8395
CPU time (s): 23.5175
CPU user time (s): 23.1734
CPU system time (s): 0.344021
CPU usage (%): 98.6492
Max. virtual memory (cumulated for all children) (KiB): 158288

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 23.1734
system time used= 0.344021
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 73959
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= 1656
involuntary context switches= 1586

runsolver used 0 second user time and 0.012 second system time

The end