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/201108300820/aspcud-1.5/b2540c52-51b7-11e0-aa4f-00163e1e087d.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//b2540c52-51b7-11e0-aa4f-00163e1e087d.cudf /home/misc2010/tmp/201108300820/aspcud-1.5/b2540c52-51b7-11e0-aa4f-00163e1e087d.cudf.dudf-real.result +sum(installedsize) 

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.15 1.03 1.01 3/35 14843
/proc/meminfo: memFree=928572/1048576 swapFree=0/0
[pid=14841] ppid=14840 vsize=2588 CPUtime=0
/proc/14841/stat : 14841 (aspcud-1.5) S 14840 14841 2160 34817 2160 4202496 373 0 0 0 0 0 0 0 25 0 1 0 57613129 2650112 279 1283457024 134512640 135304128 4294150432 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/14841/statm: 647 279 234 194 0 34 0
[pid=14842] ppid=14841 vsize=2588 CPUtime=0
/proc/14842/stat : 14842 (aspcud-1.5) R 14841 14841 2160 34817 2160 4202560 110 0 0 0 0 0 0 0 25 0 1 0 57613130 2650112 132 1283457024 134512640 135304128 4294150432 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/14842/statm: 647 132 86 194 0 34 0
[pid=14843] ppid=14842 vsize=2588 CPUtime=0
/proc/14843/stat : 14843 (aspcud-1.5) R 14842 14841 2160 34817 2160 4202560 0 0 0 0 0 0 0 0 25 0 1 0 57613130 2650112 46 1283457024 134512640 135304128 4294150432 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/14843/statm: 647 46 0 194 0 34 0

[startup+0.182102 s]
/proc/loadavg: 1.15 1.03 1.01 3/35 14843
/proc/meminfo: memFree=928572/1048576 swapFree=0/0
[pid=14841] ppid=14840 vsize=2596 CPUtime=0
/proc/14841/stat : 14841 (aspcud-1.5) S 14840 14841 2160 34817 2160 4202496 580 1521 0 0 0 0 0 0 25 0 1 0 57613129 2658304 298 1283457024 134512640 135304128 4294150432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14841/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.206019 s]
/proc/loadavg: 1.15 1.03 1.01 3/35 14843
/proc/meminfo: memFree=928572/1048576 swapFree=0/0
[pid=14841] ppid=14840 vsize=2596 CPUtime=0
/proc/14841/stat : 14841 (aspcud-1.5) S 14840 14841 2160 34817 2160 4202496 580 1521 0 0 0 0 0 0 25 0 1 0 57613129 2658304 298 1283457024 134512640 135304128 4294150432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14841/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.306045 s]
/proc/loadavg: 1.15 1.03 1.01 3/35 14843
/proc/meminfo: memFree=928572/1048576 swapFree=0/0
[pid=14841] ppid=14840 vsize=2596 CPUtime=0
/proc/14841/stat : 14841 (aspcud-1.5) S 14840 14841 2160 34817 2160 4202496 580 1521 0 0 0 0 0 0 25 0 1 0 57613129 2658304 298 1283457024 134512640 135304128 4294150432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14841/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.706082 s]
/proc/loadavg: 1.15 1.03 1.01 3/35 14843
/proc/meminfo: memFree=928572/1048576 swapFree=0/0
[pid=14841] ppid=14840 vsize=2596 CPUtime=0
/proc/14841/stat : 14841 (aspcud-1.5) S 14840 14841 2160 34817 2160 4202496 580 1521 0 0 0 0 0 0 25 0 1 0 57613129 2658304 298 1283457024 134512640 135304128 4294150432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14841/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.50612 s]
/proc/loadavg: 1.15 1.03 1.01 1/37 14852
/proc/meminfo: memFree=897952/1048576 swapFree=0/0
[pid=14841] ppid=14840 vsize=2596 CPUtime=0
/proc/14841/stat : 14841 (aspcud-1.5) S 14840 14841 2160 34817 2160 4202496 580 1521 0 0 0 0 0 0 25 0 1 0 57613129 2658304 298 1283457024 134512640 135304128 4294150432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14841/statm: 649 298 251 194 0 36 0
[pid=14850] ppid=14841 vsize=1928 CPUtime=0
/proc/14850/stat : 14850 (clasp) S 14841 14841 2160 34817 2160 4202496 276 0 16 0 0 0 0 0 23 0 1 0 57613131 1974272 159 1283457024 134512640 136285277 4289613024 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/14850/statm: 482 159 144 433 0 47 0
[pid=14851] ppid=14841 vsize=2588 CPUtime=0
/proc/14851/stat : 14851 (gringo) S 14841 14841 2160 34817 2160 4202496 383 0 22 0 0 0 0 0 21 0 1 0 57613131 2650112 272 1283457024 134512640 136933539 4288944976 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/14851/statm: 647 272 242 592 0 52 0
[pid=14852] ppid=14841 vsize=27012 CPUtime=0.94
/proc/14852/stat : 14852 (cudf2lp) R 14841 14841 2160 34817 2160 4202496 7620 0 15 0 91 3 0 0 25 0 1 0 57613131 27660288 5987 1283457024 134512640 135786343 4292766944 18446744073709551615 134585471 0 0 6 0 0 0 0 17 0 0 0 0
/proc/14852/statm: 6753 5987 128 311 0 6440 0
Current children cumulated CPU time (s) 0.94
Current children cumulated vsize (KiB) 34124

[startup+3.10705 s]
/proc/loadavg: 1.15 1.03 1.01 2/37 14852
/proc/meminfo: memFree=861008/1048576 swapFree=0/0
[pid=14841] ppid=14840 vsize=2596 CPUtime=0
/proc/14841/stat : 14841 (aspcud-1.5) S 14840 14841 2160 34817 2160 4202496 580 1521 0 0 0 0 0 0 25 0 1 0 57613129 2658304 298 1283457024 134512640 135304128 4294150432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14841/statm: 649 298 251 194 0 36 0
[pid=14850] ppid=14841 vsize=21312 CPUtime=0.07
/proc/14850/stat : 14850 (clasp) S 14841 14841 2160 34817 2160 4202496 6017 0 19 0 5 2 0 0 18 0 1 0 57613131 21823488 4839 1283457024 134512640 136285277 4289613024 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/14850/statm: 5328 4839 177 433 0 4893 0
[pid=14851] ppid=14841 vsize=30908 CPUtime=1.01
/proc/14851/stat : 14851 (gringo) S 14841 14841 2160 34817 2160 4202496 9277 0 22 0 95 6 0 0 18 0 1 0 57613131 31649792 5969 1283457024 134512640 136933539 4288944976 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/14851/statm: 7727 5969 242 592 0 7132 0
[pid=14852] ppid=14841 vsize=32744 CPUtime=1.44
/proc/14852/stat : 14852 (cudf2lp) R 14841 14841 2160 34817 2160 4202496 10526 0 15 0 140 4 0 0 25 0 1 0 57613131 33529856 7988 1283457024 134512640 135786343 4292766944 18446744073709551615 135174792 0 0 6 0 0 0 0 17 0 0 0 0
/proc/14852/statm: 8186 7988 139 311 0 7873 0
Current children cumulated CPU time (s) 2.52
Current children cumulated vsize (KiB) 87560

[startup+6.3078 s]
/proc/loadavg: 1.21 1.05 1.01 2/36 14852
/proc/meminfo: memFree=756740/1048576 swapFree=0/0
[pid=14841] ppid=14840 vsize=2596 CPUtime=1.7
/proc/14841/stat : 14841 (aspcud-1.5) S 14840 14841 2160 34817 2160 4202496 580 12050 0 15 0 0 164 6 18 0 1 0 57613129 2658304 298 1283457024 134512640 135304128 4294150432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14841/statm: 649 298 251 194 0 36 0
[pid=14850] ppid=14841 vsize=87872 CPUtime=0.42
/proc/14850/stat : 14850 (clasp) S 14841 14841 2160 34817 2160 4202496 25532 0 19 0 32 10 0 0 18 0 1 0 57613131 89980928 21221 1283457024 134512640 136285277 4289613024 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/14850/statm: 21968 21221 177 433 0 21533 0
[pid=14851] ppid=14841 vsize=141812 CPUtime=3.59
/proc/14851/stat : 14851 (gringo) R 14841 14841 2160 34817 2160 4202496 44425 0 22 0 341 18 0 0 20 0 1 0 57613131 145215488 28724 1283457024 134512640 136933539 4288944976 18446744073709551615 134611933 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14851/statm: 35453 28724 253 592 0 34858 0
Current children cumulated CPU time (s) 5.71
Current children cumulated vsize (KiB) 232280

[startup+12.7099 s]
/proc/loadavg: 1.20 1.05 1.01 2/35 14852
/proc/meminfo: memFree=784540/1048576 swapFree=0/0
[pid=14841] ppid=14840 vsize=2596 CPUtime=6.85
/proc/14841/stat : 14841 (aspcud-1.5) S 14840 14841 2160 34817 2160 4202496 580 72238 0 37 0 0 647 38 18 0 1 0 57613129 2658304 298 1283457024 134512640 135304128 4294150432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14841/statm: 649 298 251 194 0 36 0
[pid=14850] ppid=14841 vsize=123560 CPUtime=5.27
/proc/14850/stat : 14850 (clasp) R 14841 14841 2160 34817 2160 4202496 40305 0 19 0 512 15 0 0 25 0 1 0 57613131 126525440 30602 1283457024 134512640 136285277 4289613024 18446744073709551615 134963511 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/14850/statm: 30890 30602 234 433 0 30455 0
Current children cumulated CPU time (s) 12.12
Current children cumulated vsize (KiB) 126156

[startup+25.5132 s]
/proc/loadavg: 1.15 1.04 1.01 2/35 14852
/proc/meminfo: memFree=486196/1048576 swapFree=0/0
[pid=14841] ppid=14840 vsize=2596 CPUtime=6.85
/proc/14841/stat : 14841 (aspcud-1.5) S 14840 14841 2160 34817 2160 4202496 580 72238 0 37 0 0 647 38 18 0 1 0 57613129 2658304 298 1283457024 134512640 135304128 4294150432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14841/statm: 649 298 251 194 0 36 0
[pid=14850] ppid=14841 vsize=427120 CPUtime=18.07
/proc/14850/stat : 14850 (clasp) R 14841 14841 2160 34817 2160 4202496 116178 0 19 0 1775 32 0 0 25 0 1 0 57613131 437370880 106475 1283457024 134512640 136285277 4289613024 18446744073709551615 134650319 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/14850/statm: 106780 106475 234 433 0 106345 0
Current children cumulated CPU time (s) 24.92
Current children cumulated vsize (KiB) 429716

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

[startup+25.6132 s]
/proc/loadavg: 1.15 1.04 1.01 2/35 14852
/proc/meminfo: memFree=486196/1048576 swapFree=0/0
[pid=14841] ppid=14840 vsize=2596 CPUtime=6.85
/proc/14841/stat : 14841 (aspcud-1.5) S 14840 14841 2160 34817 2160 4202496 580 72238 0 37 0 0 647 38 18 0 1 0 57613129 2658304 298 1283457024 134512640 135304128 4294150432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14841/statm: 649 298 251 194 0 36 0
[pid=14850] ppid=14841 vsize=429708 CPUtime=18.17
/proc/14850/stat : 14850 (clasp) R 14841 14841 2160 34817 2160 4202496 116818 0 19 0 1785 32 0 0 25 0 1 0 57613131 440020992 107115 1283457024 134512640 136285277 4289613024 18446744073709551615 134966690 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/14850/statm: 107427 107115 234 433 0 106992 0
Current children cumulated CPU time (s) 25.02
Current children cumulated vsize (KiB) 432304

[startup+38.4059 s]
/proc/loadavg: 1.13 1.04 1.01 2/35 14852
/proc/meminfo: memFree=207816/1048576 swapFree=0/0
[pid=14841] ppid=14840 vsize=2596 CPUtime=6.85
/proc/14841/stat : 14841 (aspcud-1.5) S 14840 14841 2160 34817 2160 4202496 580 72238 0 37 0 0 647 38 18 0 1 0 57613129 2658304 298 1283457024 134512640 135304128 4294150432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14841/statm: 649 298 251 194 0 36 0
[pid=14850] ppid=14841 vsize=726992 CPUtime=30.95
/proc/14850/stat : 14850 (clasp) R 14841 14841 2160 34817 2160 4202496 191157 0 19 0 3040 55 0 0 25 0 1 0 57613131 744439808 181454 1283457024 134512640 136285277 4289613024 18446744073709551615 134651288 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/14850/statm: 181748 181454 234 433 0 181313 0
Current children cumulated CPU time (s) 37.8
Current children cumulated vsize (KiB) 729588

[startup+44.8081 s]
/proc/loadavg: 1.12 1.04 1.01 2/35 14852
/proc/meminfo: memFree=4212/1048576 swapFree=0/0
[pid=14841] ppid=14840 vsize=2596 CPUtime=6.85
/proc/14841/stat : 14841 (aspcud-1.5) S 14840 14841 2160 34817 2160 4202496 580 72238 0 37 0 0 647 38 18 0 1 0 57613129 2658304 298 1283457024 134512640 135304128 4294150432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14841/statm: 649 298 251 194 0 36 0
[pid=14850] ppid=14841 vsize=930060 CPUtime=37.31
/proc/14850/stat : 14850 (clasp) R 14841 14841 2160 34817 2160 4202496 241911 0 19 0 3663 68 0 0 25 0 1 0 57613131 952381440 232208 1283457024 134512640 136285277 4289613024 18446744073709551615 134985131 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/14850/statm: 232515 232208 234 433 0 232080 0
Current children cumulated CPU time (s) 44.16
Current children cumulated vsize (KiB) 932656

[startup+46.4071 s]
/proc/loadavg: 1.19 1.06 1.02 2/35 14852
/proc/meminfo: memFree=4216/1048576 swapFree=0/0
[pid=14841] ppid=14840 vsize=2596 CPUtime=6.85
/proc/14841/stat : 14841 (aspcud-1.5) S 14840 14841 2160 34817 2160 4202496 580 72238 0 37 0 0 647 38 18 0 1 0 57613129 2658304 298 1283457024 134512640 135304128 4294150432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14841/statm: 649 298 251 194 0 36 0
[pid=14850] ppid=14841 vsize=961648 CPUtime=38.8
/proc/14850/stat : 14850 (clasp) R 14841 14841 2160 34817 2160 4202496 249780 0 19 0 3809 71 0 0 25 0 1 0 57613131 984727552 240077 1283457024 134512640 136285277 4289613024 18446744073709551615 134964956 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/14850/statm: 240412 240077 234 433 0 239977 0
Current children cumulated CPU time (s) 45.65
Current children cumulated vsize (KiB) 964244

[startup+47.2072 s]
/proc/loadavg: 1.19 1.06 1.02 2/35 14852
/proc/meminfo: memFree=4216/1048576 swapFree=0/0
[pid=14841] ppid=14840 vsize=2596 CPUtime=6.85
/proc/14841/stat : 14841 (aspcud-1.5) S 14840 14841 2160 34817 2160 4202496 580 72238 0 37 0 0 647 38 18 0 1 0 57613129 2658304 298 1283457024 134512640 135304128 4294150432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14841/statm: 649 298 251 194 0 36 0
[pid=14850] ppid=14841 vsize=979280 CPUtime=39.6
/proc/14850/stat : 14850 (clasp) R 14841 14841 2160 34817 2160 4202496 254211 0 19 0 3885 75 0 0 25 0 1 0 57613131 1002782720 244508 1283457024 134512640 136285277 4289613024 18446744073709551615 134966723 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/14850/statm: 244820 244508 234 433 0 244385 0
Current children cumulated CPU time (s) 46.45
Current children cumulated vsize (KiB) 981876

[startup+48.2731 s]
/proc/loadavg: 1.19 1.06 1.02 2/35 14852
/proc/meminfo: memFree=4356/1048576 swapFree=0/0
[pid=14841] ppid=14840 vsize=2596 CPUtime=46.86
/proc/14841/stat : 14841 (aspcud-1.5) D 14840 14841 2160 34817 2160 4202496 643 327804 11 60 0 0 4554 132 18 0 1 0 57613129 2658304 121 1283457024 134512640 135304128 4294150432 18446744073709551615 4158756251 0 65536 4 1132560123 18446744071564332000 0 0 17 0 0 0 0
/proc/14841/statm: 649 121 74 194 0 36 0
Current children cumulated CPU time (s) 46.86
Current children cumulated vsize (KiB) 2596

[startup+48.4051 s]
/proc/loadavg: 1.19 1.06 1.02 2/35 14852
/proc/meminfo: memFree=4356/1048576 swapFree=0/0
[pid=14841] ppid=14840 vsize=2596 CPUtime=46.86
/proc/14841/stat : 14841 (aspcud-1.5) S 14840 14841 2160 34817 2160 4202496 737 327804 16 60 0 0 4554 132 18 0 1 0 57613129 2658304 203 1283457024 134512640 135304128 4294150432 18446744073709551615 4294960130 0 65536 16902 1132543225 18446744071564329979 0 0 17 0 0 0 0
/proc/14841/statm: 649 203 156 194 0 36 0
Current children cumulated CPU time (s) 46.86
Current children cumulated vsize (KiB) 2596

[startup+48.5051 s]
/proc/loadavg: 1.19 1.06 1.02 2/35 14852
/proc/meminfo: memFree=4356/1048576 swapFree=0/0
[pid=14841] ppid=14840 vsize=2600 CPUtime=46.86
/proc/14841/stat : 14841 (aspcud-1.5) S 14840 14841 2160 34817 2160 4202496 1028 329943 16 70 0 0 4554 132 25 0 1 0 57613129 2662400 235 1283457024 134512640 135304128 4294150432 18446744073709551615 4294960130 0 65536 16902 1132543225 18446744071564329979 0 0 17 0 0 0 0
/proc/14841/statm: 650 235 187 194 0 37 0
Current children cumulated CPU time (s) 46.86
Current children cumulated vsize (KiB) 2600

Child status: 0
Real time (s): 48.5178
CPU time (s): 46.8789
CPU user time (s): 45.5428
CPU system time (s): 1.33608
CPU usage (%): 96.6222
Max. virtual memory (cumulated for all children) (KiB): 986496

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 45.5428
system time used= 1.33608
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 331176
page faults= 87
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 8847
involuntary context switches= 8146

runsolver used 0 second user time and 0.068004 second system time

The end