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/rand390.cudf.dudf-random.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-random//rand390.cudf /home/misc2010/tmp/201109011757/aspcud-1.5/rand390.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.06 1.02 0.90 5/40 24518 /proc/meminfo: memFree=617136/1048576 swapFree=0/0 [pid=24516] ppid=24515 vsize=2592 CPUtime=0 /proc/24516/stat : 24516 (aspcud-1.5) S 24515 24516 22717 34817 22717 4202496 374 0 0 0 0 0 0 0 21 0 1 0 71828629 2654208 280 1283457024 134512640 135304128 4286661088 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/24516/statm: 648 280 234 194 0 35 0 [pid=24517] ppid=24516 vsize=2592 CPUtime=0 /proc/24517/stat : 24517 (aspcud-1.5) R 24516 24516 22717 34817 22717 4202560 110 0 0 0 0 0 0 0 25 0 1 0 71828629 2654208 133 1283457024 134512640 135304128 4286661088 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/24517/statm: 648 133 86 194 0 35 0 [pid=24518] ppid=24517 vsize=2592 CPUtime=0 /proc/24518/stat : 24518 (aspcud-1.5) R 24517 24516 22717 34817 22717 4202560 0 0 0 0 0 0 0 0 25 0 1 0 71828629 2654208 47 1283457024 134512640 135304128 4286661088 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/24518/statm: 648 47 0 194 0 35 0 [startup+0.164362 s] /proc/loadavg: 1.06 1.02 0.90 5/40 24518 /proc/meminfo: memFree=617136/1048576 swapFree=0/0 [pid=24516] ppid=24515 vsize=2600 CPUtime=0 /proc/24516/stat : 24516 (aspcud-1.5) S 24515 24516 22717 34817 22717 4202496 583 1521 0 0 0 0 0 0 25 0 1 0 71828629 2662400 299 1283457024 134512640 135304128 4286661088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24516/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.204371 s] /proc/loadavg: 1.06 1.02 0.90 5/40 24518 /proc/meminfo: memFree=617136/1048576 swapFree=0/0 [pid=24516] ppid=24515 vsize=2600 CPUtime=0 /proc/24516/stat : 24516 (aspcud-1.5) S 24515 24516 22717 34817 22717 4202496 583 1521 0 0 0 0 0 0 25 0 1 0 71828629 2662400 299 1283457024 134512640 135304128 4286661088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24516/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.30366 s] /proc/loadavg: 1.06 1.02 0.90 5/40 24518 /proc/meminfo: memFree=617136/1048576 swapFree=0/0 [pid=24516] ppid=24515 vsize=2600 CPUtime=0 /proc/24516/stat : 24516 (aspcud-1.5) S 24515 24516 22717 34817 22717 4202496 583 1521 0 0 0 0 0 0 25 0 1 0 71828629 2662400 299 1283457024 134512640 135304128 4286661088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24516/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.707652 s] /proc/loadavg: 1.06 1.02 0.90 5/40 24518 /proc/meminfo: memFree=617136/1048576 swapFree=0/0 [pid=24516] ppid=24515 vsize=2600 CPUtime=0 /proc/24516/stat : 24516 (aspcud-1.5) S 24515 24516 22717 34817 22717 4202496 583 1521 0 0 0 0 0 0 25 0 1 0 71828629 2662400 299 1283457024 134512640 135304128 4286661088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24516/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+1.5119 s] /proc/loadavg: 1.06 1.02 0.90 2/42 24528 /proc/meminfo: memFree=584388/1048576 swapFree=0/0 [pid=24516] ppid=24515 vsize=2600 CPUtime=0 /proc/24516/stat : 24516 (aspcud-1.5) S 24515 24516 22717 34817 22717 4202496 583 1521 0 0 0 0 0 0 25 0 1 0 71828629 2662400 299 1283457024 134512640 135304128 4286661088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24516/statm: 650 299 251 194 0 37 0 [pid=24525] ppid=24516 vsize=1924 CPUtime=0.01 /proc/24525/stat : 24525 (clasp) S 24516 24516 22717 34817 22717 4202496 291 0 0 0 1 0 0 0 25 0 1 0 71828630 1970176 159 1283457024 134512640 136285277 4289830160 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/24525/statm: 481 159 144 433 0 46 0 [pid=24526] ppid=24516 vsize=2588 CPUtime=0 /proc/24526/stat : 24526 (gringo) S 24516 24516 22717 34817 22717 4202496 404 0 0 0 0 0 0 0 25 0 1 0 71828630 2650112 272 1283457024 134512640 136933539 4287265568 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/24526/statm: 647 272 242 592 0 52 0 [pid=24527] ppid=24516 vsize=29444 CPUtime=1.31 /proc/24527/stat : 24527 (cudf2lp) R 24516 24516 22717 34817 22717 4202496 8170 0 0 0 129 2 0 0 25 0 1 0 71828630 30150656 6669 1283457024 134512640 135786343 4289830224 18446744073709551615 135220081 0 0 6 0 0 0 0 17 0 0 0 0 /proc/24527/statm: 7361 6669 128 311 0 7048 0 Current children cumulated CPU time (s) 1.32 Current children cumulated vsize (KiB) 36556 [startup+3.11296 s] /proc/loadavg: 1.06 1.02 0.90 2/42 24528 /proc/meminfo: memFree=542020/1048576 swapFree=0/0 [pid=24516] ppid=24515 vsize=2600 CPUtime=0 /proc/24516/stat : 24516 (aspcud-1.5) S 24515 24516 22717 34817 22717 4202496 583 1521 0 0 0 0 0 0 25 0 1 0 71828629 2662400 299 1283457024 134512640 135304128 4286661088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24516/statm: 650 299 251 194 0 37 0 [pid=24525] ppid=24516 vsize=11492 CPUtime=0.06 /proc/24525/stat : 24525 (clasp) S 24516 24516 22717 34817 22717 4202496 3064 0 0 0 6 0 0 0 18 0 1 0 71828630 11767808 2546 1283457024 134512640 136285277 4289830160 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/24525/statm: 2873 2546 177 433 0 2438 0 [pid=24526] ppid=24516 vsize=16124 CPUtime=0.54 /proc/24526/stat : 24526 (gringo) S 24516 24516 22717 34817 22717 4202496 4621 0 0 0 54 0 0 0 18 0 1 0 71828630 16510976 3056 1283457024 134512640 136933539 4287265568 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/24526/statm: 4031 3056 242 592 0 3436 0 [pid=24527] ppid=24516 vsize=25476 CPUtime=2.26 /proc/24527/stat : 24527 (cudf2lp) R 24516 24516 22717 34817 22717 4202496 14082 0 0 0 222 4 0 0 25 0 1 0 71828630 26087424 6193 1283457024 134512640 135786343 4289830224 18446744073709551615 134922544 0 0 6 0 0 0 0 17 0 0 0 0 /proc/24527/statm: 6369 6193 139 311 0 6056 0 Current children cumulated CPU time (s) 2.86 Current children cumulated vsize (KiB) 55692 [startup+6.31361 s] /proc/loadavg: 1.14 1.03 0.91 2/40 24528 /proc/meminfo: memFree=554452/1048576 swapFree=0/0 [pid=24516] ppid=24515 vsize=2600 CPUtime=3.59 /proc/24516/stat : 24516 (aspcud-1.5) S 24515 24516 22717 34817 22717 4202496 583 29275 0 0 0 0 348 11 18 0 1 0 71828629 2662400 299 1283457024 134512640 135304128 4286661088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24516/statm: 650 299 251 194 0 37 0 [pid=24525] ppid=24516 vsize=42784 CPUtime=2.46 /proc/24525/stat : 24525 (clasp) R 24516 24516 22717 34817 22717 4202496 12395 0 0 0 244 2 0 0 21 0 1 0 71828630 43810816 10462 1283457024 134512640 136285277 4289830160 18446744073709551615 134733705 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24525/statm: 10696 10462 234 433 0 10261 0 Current children cumulated CPU time (s) 6.05 Current children cumulated vsize (KiB) 45384 [startup+12.7051 s] /proc/loadavg: 1.12 1.03 0.91 2/39 24528 /proc/meminfo: memFree=504124/1048576 swapFree=0/0 [pid=24516] ppid=24515 vsize=2600 CPUtime=3.59 /proc/24516/stat : 24516 (aspcud-1.5) S 24515 24516 22717 34817 22717 4202496 583 29275 0 0 0 0 348 11 18 0 1 0 71828629 2662400 299 1283457024 134512640 135304128 4286661088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24516/statm: 650 299 251 194 0 37 0 [pid=24525] ppid=24516 vsize=86520 CPUtime=8.85 /proc/24525/stat : 24525 (clasp) R 24516 24516 22717 34817 22717 4202496 23579 0 0 0 879 6 0 0 25 0 1 0 71828630 88596480 21416 1283457024 134512640 136285277 4289830160 18446744073709551615 134959921 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24525/statm: 21630 21416 234 433 0 21195 0 Current children cumulated CPU time (s) 12.44 Current children cumulated vsize (KiB) 89120 [startup+25.5072 s] /proc/loadavg: 1.10 1.03 0.91 2/39 24528 /proc/meminfo: memFree=499784/1048576 swapFree=0/0 [pid=24516] ppid=24515 vsize=2600 CPUtime=3.59 /proc/24516/stat : 24516 (aspcud-1.5) S 24515 24516 22717 34817 22717 4202496 583 29275 0 0 0 0 348 11 18 0 1 0 71828629 2662400 299 1283457024 134512640 135304128 4286661088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24516/statm: 650 299 251 194 0 37 0 [pid=24525] ppid=24516 vsize=90884 CPUtime=21.66 /proc/24525/stat : 24525 (clasp) R 24516 24516 22717 34817 22717 4202496 24825 0 0 0 2160 6 0 0 25 0 1 0 71828630 93065216 22509 1283457024 134512640 136285277 4289830160 18446744073709551615 134723339 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24525/statm: 22721 22509 234 433 0 22286 0 Current children cumulated CPU time (s) 25.25 Current children cumulated vsize (KiB) 93484 [startup+51.1124 s] /proc/loadavg: 1.06 1.03 0.91 2/39 24528 /proc/meminfo: memFree=475976/1048576 swapFree=0/0 [pid=24516] ppid=24515 vsize=2600 CPUtime=3.59 /proc/24516/stat : 24516 (aspcud-1.5) S 24515 24516 22717 34817 22717 4202496 583 29275 0 0 0 0 348 11 18 0 1 0 71828629 2662400 299 1283457024 134512640 135304128 4286661088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24516/statm: 650 299 251 194 0 37 0 [pid=24525] ppid=24516 vsize=115204 CPUtime=47.25 /proc/24525/stat : 24525 (clasp) R 24516 24516 22717 34817 22717 4202496 30902 0 0 0 4719 6 0 0 25 0 1 0 71828630 117968896 28586 1283457024 134512640 136285277 4289830160 18446744073709551615 134963435 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24525/statm: 28801 28586 234 433 0 28366 0 Current children cumulated CPU time (s) 50.84 Current children cumulated vsize (KiB) 117804 [startup+102.303 s] /proc/loadavg: 1.03 1.02 0.91 2/38 24528 /proc/meminfo: memFree=256008/1048576 swapFree=0/0 [pid=24516] ppid=24515 vsize=2600 CPUtime=3.59 /proc/24516/stat : 24516 (aspcud-1.5) S 24515 24516 22717 34817 22717 4202496 583 29275 0 0 0 0 348 11 18 0 1 0 71828629 2662400 299 1283457024 134512640 135304128 4286661088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24516/statm: 650 299 251 194 0 37 0 [pid=24525] ppid=24516 vsize=336048 CPUtime=98.39 /proc/24525/stat : 24525 (clasp) R 24516 24516 22717 34817 22717 4202496 86104 0 0 0 9816 23 0 0 25 0 1 0 71828630 344113152 83788 1283457024 134512640 136285277 4289830160 18446744073709551615 134628499 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24525/statm: 84012 83788 234 433 0 83577 0 Current children cumulated CPU time (s) 101.98 Current children cumulated vsize (KiB) 338648 [startup+162.307 s] /proc/loadavg: 1.01 1.02 0.91 2/38 24528 /proc/meminfo: memFree=81912/1048576 swapFree=0/0 [pid=24516] ppid=24515 vsize=2600 CPUtime=3.59 /proc/24516/stat : 24516 (aspcud-1.5) S 24515 24516 22717 34817 22717 4202496 583 29275 0 0 0 0 348 11 18 0 1 0 71828629 2662400 299 1283457024 134512640 135304128 4286661088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24516/statm: 650 299 251 194 0 37 0 [pid=24525] ppid=24516 vsize=508440 CPUtime=158.36 /proc/24525/stat : 24525 (clasp) R 24516 24516 22717 34817 22717 4202496 129194 0 0 0 15790 46 0 0 25 0 1 0 71828630 520642560 126878 1283457024 134512640 136285277 4289830160 18446744073709551615 134723339 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24525/statm: 127110 126878 234 433 0 126675 0 Current children cumulated CPU time (s) 161.95 Current children cumulated vsize (KiB) 511040 [startup+222.309 s] /proc/loadavg: 1.00 1.01 0.91 2/38 24528 /proc/meminfo: memFree=5916/1048576 swapFree=0/0 [pid=24516] ppid=24515 vsize=2600 CPUtime=3.59 /proc/24516/stat : 24516 (aspcud-1.5) S 24515 24516 22717 34817 22717 4202496 583 29275 0 0 0 0 348 11 18 0 1 0 71828629 2662400 299 1283457024 134512640 135304128 4286661088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24516/statm: 650 299 251 194 0 37 0 [pid=24525] ppid=24516 vsize=674136 CPUtime=218.29 /proc/24525/stat : 24525 (clasp) R 24516 24516 22717 34817 22717 4202496 170720 0 0 0 21765 64 0 0 25 0 1 0 71828630 690315264 168255 1283457024 134512640 136285277 4289830160 18446744073709551615 134948754 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24525/statm: 168534 168255 234 433 0 168099 0 Current children cumulated CPU time (s) 221.88 Current children cumulated vsize (KiB) 676736 [startup+282.313 s] /proc/loadavg: 1.00 1.00 0.91 2/38 24528 /proc/meminfo: memFree=6072/1048576 swapFree=0/0 [pid=24516] ppid=24515 vsize=2600 CPUtime=3.59 /proc/24516/stat : 24516 (aspcud-1.5) S 24515 24516 22717 34817 22717 4202496 583 29275 0 0 0 0 348 11 18 0 1 0 71828629 2662400 299 1283457024 134512640 135304128 4286661088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24516/statm: 650 299 251 194 0 37 0 [pid=24525] ppid=24516 vsize=703616 CPUtime=278.21 /proc/24525/stat : 24525 (clasp) R 24516 24516 22717 34817 22717 4202496 178108 0 0 0 27750 71 0 0 25 0 1 0 71828630 720502784 175643 1283457024 134512640 136285277 4289830160 18446744073709551615 134622827 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24525/statm: 175904 175643 234 433 0 175469 0 Current children cumulated CPU time (s) 281.8 Current children cumulated vsize (KiB) 706216 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.605 s] /proc/loadavg: 1.00 1.00 0.91 2/38 24528 /proc/meminfo: memFree=6072/1048576 swapFree=0/0 [pid=24516] ppid=24515 vsize=2600 CPUtime=3.59 /proc/24516/stat : 24516 (aspcud-1.5) S 24515 24516 22717 34817 22717 4202496 583 29275 0 0 0 0 348 11 18 0 1 0 71828629 2662400 299 1283457024 134512640 135304128 4286661088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24516/statm: 650 299 251 194 0 37 0 [pid=24525] ppid=24516 vsize=703616 CPUtime=286.48 /proc/24525/stat : 24525 (clasp) R 24516 24516 22717 34817 22717 4202496 178108 0 0 0 28577 71 0 0 25 0 1 0 71828630 720502784 175643 1283457024 134512640 136285277 4289830160 18446744073709551615 134964967 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24525/statm: 175904 175643 234 433 0 175469 0 Current children cumulated CPU time (s) 290.07 Current children cumulated vsize (KiB) 706216 Sending User defined signal 1 to process tree (bottom up) Sleeping 10 seconds Solver just ended. Dumping a history of the last processes samples [startup+290.716 s] /proc/loadavg: 1.00 1.00 0.91 2/38 24528 /proc/meminfo: memFree=6072/1048576 swapFree=0/0 [pid=24516] ppid=24515 vsize=2600 CPUtime=290.12 /proc/24516/stat : 24516 (aspcud-1.5) S 24515 24516 22717 34817 22717 4202496 609 207391 0 0 0 0 28925 87 19 0 1 0 71828629 2662400 306 1283457024 134512640 135304128 4286661088 18446744073709551615 4294960130 0 65536 16902 1132543225 18446744071564329979 0 0 17 0 0 0 0 /proc/24516/statm: 650 306 258 194 0 37 0 Current children cumulated CPU time (s) 290.12 Current children cumulated vsize (KiB) 2600 Child status: 0 Real time (s): 290.777 CPU time (s): 290.138 CPU user time (s): 289.262 CPU system time (s): 0.876054 CPU usage (%): 99.7804 Max. virtual memory (cumulated for all children) (KiB): 706216 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.262 system time used= 0.876054 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 211545 page faults= 9 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 1689 involuntary context switches= 4834 runsolver used 0 second user time and 0.008 second system time The end