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/201108311143/aspuncud-user-1.0/56e31304-c17a-11df-b070-00163e3d3b7c.cudf.dudf-real.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-real//56e31304-c17a-11df-b070-00163e3d3b7c.cudf /home/misc2010/tmp/201108311143/aspuncud-user-1.0/56e31304-c17a-11df-b070-00163e3d3b7c.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: 0.99 0.98 0.99 5/37 29555 /proc/meminfo: memFree=644228/1048576 swapFree=0/0 [pid=29552] ppid=29551 vsize=2588 CPUtime=0 /proc/29552/stat : 29552 (aspuncud-user-1) S 29551 29552 19908 34817 19908 4202496 372 0 0 0 0 0 0 0 18 0 1 0 65532931 2650112 279 1283457024 134512640 135304128 4289674432 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/29552/statm: 647 279 234 194 0 34 0 [pid=29553] ppid=29552 vsize=2588 CPUtime=0 /proc/29553/stat : 29553 (aspuncud-user-1) S 29552 29552 19908 34817 19908 4202560 119 0 0 0 0 0 0 0 18 0 1 0 65532932 2650112 133 1283457024 134512640 135304128 4289674432 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0 /proc/29553/statm: 647 133 87 194 0 34 0 [pid=29554] ppid=29553 vsize=2588 CPUtime=0 /proc/29554/stat : 29554 (aspuncud-user-1) R 29553 29552 19908 34817 19908 4202560 127 0 0 0 0 0 0 0 25 0 1 0 65532932 2650112 150 1283457024 134512640 135304128 4289674432 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/29554/statm: 647 150 104 194 0 34 0 [pid=29555] ppid=29554 vsize=2588 CPUtime=0 /proc/29555/stat : 29555 (aspuncud-user-1) R 29554 29552 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 65532932 2650112 46 1283457024 134512640 135304128 4289674432 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/29555/statm: 647 46 0 194 0 34 0 [startup+0.184902 s] /proc/loadavg: 0.99 0.98 0.99 5/37 29555 /proc/meminfo: memFree=644228/1048576 swapFree=0/0 [pid=29552] ppid=29551 vsize=2592 CPUtime=0 /proc/29552/stat : 29552 (aspuncud-user-1) S 29551 29552 19908 34817 19908 4202496 570 1521 0 0 0 0 0 0 25 0 1 0 65532931 2654208 297 1283457024 134512640 135304128 4289674432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29552/statm: 648 297 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.2049 s] /proc/loadavg: 0.99 0.98 0.99 5/37 29555 /proc/meminfo: memFree=644228/1048576 swapFree=0/0 [pid=29552] ppid=29551 vsize=2592 CPUtime=0 /proc/29552/stat : 29552 (aspuncud-user-1) S 29551 29552 19908 34817 19908 4202496 570 1521 0 0 0 0 0 0 25 0 1 0 65532931 2654208 297 1283457024 134512640 135304128 4289674432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29552/statm: 648 297 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.30493 s] /proc/loadavg: 0.99 0.98 0.99 5/37 29555 /proc/meminfo: memFree=644228/1048576 swapFree=0/0 [pid=29552] ppid=29551 vsize=2592 CPUtime=0 /proc/29552/stat : 29552 (aspuncud-user-1) S 29551 29552 19908 34817 19908 4202496 570 1521 0 0 0 0 0 0 25 0 1 0 65532931 2654208 297 1283457024 134512640 135304128 4289674432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29552/statm: 648 297 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.705008 s] /proc/loadavg: 0.99 0.98 0.99 5/37 29555 /proc/meminfo: memFree=644228/1048576 swapFree=0/0 [pid=29552] ppid=29551 vsize=2592 CPUtime=0 /proc/29552/stat : 29552 (aspuncud-user-1) S 29551 29552 19908 34817 19908 4202496 570 1521 0 0 0 0 0 0 25 0 1 0 65532931 2654208 297 1283457024 134512640 135304128 4289674432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29552/statm: 648 297 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+1.50518 s] /proc/loadavg: 0.99 0.98 0.99 2/38 29563 /proc/meminfo: memFree=619416/1048576 swapFree=0/0 [pid=29552] ppid=29551 vsize=2592 CPUtime=0 /proc/29552/stat : 29552 (aspuncud-user-1) S 29551 29552 19908 34817 19908 4202496 570 1521 0 0 0 0 0 0 25 0 1 0 65532931 2654208 297 1283457024 134512640 135304128 4289674432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29552/statm: 648 297 251 194 0 35 0 [pid=29561] ppid=29552 vsize=3444 CPUtime=0 /proc/29561/stat : 29561 (unclasp) S 29552 29552 19908 34817 19908 4202496 407 0 0 0 0 0 0 0 25 0 1 0 65532932 3526656 272 1283457024 134512640 135121179 4293579040 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/29561/statm: 861 272 240 149 0 52 0 [pid=29562] ppid=29552 vsize=2692 CPUtime=0 /proc/29562/stat : 29562 (gringo) S 29552 29552 19908 34817 19908 4202496 408 0 0 0 0 0 0 0 25 0 1 0 65532933 2756608 281 1283457024 134512640 137056543 4293628080 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/29562/statm: 673 281 252 622 0 48 0 [pid=29563] ppid=29552 vsize=38060 CPUtime=1.5 /proc/29563/stat : 29563 (cudf2lp) R 29552 29552 19908 34817 19908 4202496 10657 0 0 0 146 4 0 0 25 0 1 0 65532933 38973440 9015 1283457024 134512640 135786343 4293503232 18446744073709551615 134581917 0 0 6 0 0 0 0 17 0 0 0 0 /proc/29563/statm: 9515 9015 135 311 0 9202 0 Current children cumulated CPU time (s) 1.5 Current children cumulated vsize (KiB) 46788 [startup+3.1056 s] /proc/loadavg: 0.99 0.98 0.99 3/37 29563 /proc/meminfo: memFree=639404/1048576 swapFree=0/0 [pid=29552] ppid=29551 vsize=2592 CPUtime=1.82 /proc/29552/stat : 29552 (aspuncud-user-1) S 29551 29552 19908 34817 19908 4202496 571 14698 0 0 0 0 176 6 17 0 1 0 65532931 2654208 297 1283457024 134512640 135304128 4289674432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29552/statm: 648 297 251 194 0 35 0 [pid=29561] ppid=29552 vsize=16480 CPUtime=1.26 /proc/29561/stat : 29561 (unclasp) R 29552 29552 19908 34817 19908 4202496 3927 0 0 0 124 2 0 0 19 0 1 0 65532932 16875520 3583 1283457024 134512640 135121179 4293579040 18446744073709551615 134891805 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/29561/statm: 4120 3583 323 149 0 3311 0 Current children cumulated CPU time (s) 3.08 Current children cumulated vsize (KiB) 19072 [startup+6.30641 s] /proc/loadavg: 0.99 0.98 0.99 2/36 29563 /proc/meminfo: memFree=617340/1048576 swapFree=0/0 [pid=29552] ppid=29551 vsize=2592 CPUtime=1.82 /proc/29552/stat : 29552 (aspuncud-user-1) S 29551 29552 19908 34817 19908 4202496 571 14698 0 0 0 0 176 6 17 0 1 0 65532931 2654208 297 1283457024 134512640 135304128 4289674432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29552/statm: 648 297 251 194 0 35 0 [pid=29561] ppid=29552 vsize=33296 CPUtime=4.46 /proc/29561/stat : 29561 (unclasp) R 29552 29552 19908 34817 19908 4202496 8284 0 0 0 443 3 0 0 25 0 1 0 65532932 34095104 7792 1283457024 134512640 135121179 4293579040 18446744073709551615 134890949 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/29561/statm: 8324 7792 324 149 0 7515 0 Current children cumulated CPU time (s) 6.28 Current children cumulated vsize (KiB) 35888 [startup+12.7082 s] /proc/loadavg: 0.99 0.98 0.99 2/36 29563 /proc/meminfo: memFree=588456/1048576 swapFree=0/0 [pid=29552] ppid=29551 vsize=2592 CPUtime=1.82 /proc/29552/stat : 29552 (aspuncud-user-1) S 29551 29552 19908 34817 19908 4202496 571 14698 0 0 0 0 176 6 17 0 1 0 65532931 2654208 297 1283457024 134512640 135304128 4289674432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29552/statm: 648 297 251 194 0 35 0 [pid=29561] ppid=29552 vsize=61724 CPUtime=10.86 /proc/29561/stat : 29561 (unclasp) R 29552 29552 19908 34817 19908 4202496 15552 0 0 0 1075 11 0 0 25 0 1 0 65532932 63205376 14838 1283457024 134512640 135121179 4293579040 18446744073709551615 4159263813 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/29561/statm: 15431 14838 324 149 0 14622 0 Current children cumulated CPU time (s) 12.68 Current children cumulated vsize (KiB) 64316 [startup+25.5121 s] /proc/loadavg: 0.99 0.98 0.99 2/36 29563 /proc/meminfo: memFree=535880/1048576 swapFree=0/0 [pid=29552] ppid=29551 vsize=2592 CPUtime=1.82 /proc/29552/stat : 29552 (aspuncud-user-1) S 29551 29552 19908 34817 19908 4202496 571 14698 0 0 0 0 176 6 17 0 1 0 65532931 2654208 297 1283457024 134512640 135304128 4289674432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29552/statm: 648 297 251 194 0 35 0 [pid=29561] ppid=29552 vsize=112984 CPUtime=23.67 /proc/29561/stat : 29561 (unclasp) R 29552 29552 19908 34817 19908 4202496 28620 0 0 0 2352 15 0 0 25 0 1 0 65532932 115695616 27574 1283457024 134512640 135121179 4293579040 18446744073709551615 134891771 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/29561/statm: 28246 27574 324 149 0 27437 0 Current children cumulated CPU time (s) 25.49 Current children cumulated vsize (KiB) 115576 [startup+51.1118 s] /proc/loadavg: 0.99 0.98 0.99 2/35 29563 /proc/meminfo: memFree=465828/1048576 swapFree=0/0 [pid=29552] ppid=29551 vsize=2592 CPUtime=1.82 /proc/29552/stat : 29552 (aspuncud-user-1) S 29551 29552 19908 34817 19908 4202496 571 14698 0 0 0 0 176 6 17 0 1 0 65532931 2654208 297 1283457024 134512640 135304128 4289674432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29552/statm: 648 297 251 194 0 35 0 [pid=29561] ppid=29552 vsize=183392 CPUtime=49.24 /proc/29561/stat : 29561 (unclasp) R 29552 29552 19908 34817 19908 4202496 46241 0 0 0 4905 19 0 0 25 0 1 0 65532932 187793408 45195 1283457024 134512640 135121179 4293579040 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/29561/statm: 45848 45195 324 149 0 45039 0 Current children cumulated CPU time (s) 51.06 Current children cumulated vsize (KiB) 185984 [startup+102.312 s] /proc/loadavg: 0.99 0.98 0.99 2/35 29563 /proc/meminfo: memFree=385972/1048576 swapFree=0/0 [pid=29552] ppid=29551 vsize=2592 CPUtime=1.82 /proc/29552/stat : 29552 (aspuncud-user-1) S 29551 29552 19908 34817 19908 4202496 571 14698 0 0 0 0 176 6 17 0 1 0 65532931 2654208 297 1283457024 134512640 135304128 4289674432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29552/statm: 648 297 251 194 0 35 0 [pid=29561] ppid=29552 vsize=262744 CPUtime=100.44 /proc/29561/stat : 29561 (unclasp) R 29552 29552 19908 34817 19908 4202496 66650 0 0 0 10020 24 0 0 25 0 1 0 65532932 269049856 64718 1283457024 134512640 135121179 4293579040 18446744073709551615 134873589 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/29561/statm: 65686 64718 329 149 0 64877 0 Current children cumulated CPU time (s) 102.26 Current children cumulated vsize (KiB) 265336 [startup+162.313 s] /proc/loadavg: 0.99 0.98 0.99 2/35 29563 /proc/meminfo: memFree=327692/1048576 swapFree=0/0 [pid=29552] ppid=29551 vsize=2592 CPUtime=1.82 /proc/29552/stat : 29552 (aspuncud-user-1) S 29551 29552 19908 34817 19908 4202496 571 14698 0 0 0 0 176 6 17 0 1 0 65532931 2654208 297 1283457024 134512640 135304128 4289674432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29552/statm: 648 297 251 194 0 35 0 [pid=29561] ppid=29552 vsize=321724 CPUtime=160.37 /proc/29561/stat : 29561 (unclasp) R 29552 29552 19908 34817 19908 4202496 81582 0 0 0 16008 29 0 0 25 0 1 0 65532932 329445376 79253 1283457024 134512640 135121179 4293579040 18446744073709551615 134891771 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/29561/statm: 80431 79253 329 149 0 79622 0 Current children cumulated CPU time (s) 162.19 Current children cumulated vsize (KiB) 324316 [startup+222.303 s] /proc/loadavg: 0.99 0.98 0.99 2/35 29563 /proc/meminfo: memFree=246472/1048576 swapFree=0/0 [pid=29552] ppid=29551 vsize=2592 CPUtime=1.82 /proc/29552/stat : 29552 (aspuncud-user-1) S 29551 29552 19908 34817 19908 4202496 571 14698 0 0 0 0 176 6 17 0 1 0 65532931 2654208 297 1283457024 134512640 135304128 4289674432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29552/statm: 648 297 251 194 0 35 0 [pid=29561] ppid=29552 vsize=404408 CPUtime=220.33 /proc/29561/stat : 29561 (unclasp) R 29552 29552 19908 34817 19908 4202496 102615 0 0 0 21999 34 0 0 25 0 1 0 65532932 414113792 99722 1283457024 134512640 135121179 4293579040 18446744073709551615 134891769 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/29561/statm: 101102 99722 329 149 0 100293 0 Current children cumulated CPU time (s) 222.15 Current children cumulated vsize (KiB) 407000 [startup+282.314 s] /proc/loadavg: 0.99 0.98 0.99 2/35 29563 /proc/meminfo: memFree=176536/1048576 swapFree=0/0 [pid=29552] ppid=29551 vsize=2592 CPUtime=1.82 /proc/29552/stat : 29552 (aspuncud-user-1) S 29551 29552 19908 34817 19908 4202496 571 14698 0 0 0 0 176 6 17 0 1 0 65532931 2654208 297 1283457024 134512640 135304128 4289674432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29552/statm: 648 297 251 194 0 35 0 [pid=29561] ppid=29552 vsize=476312 CPUtime=280.28 /proc/29561/stat : 29561 (unclasp) R 29552 29552 19908 34817 19908 4202496 124925 0 0 0 27984 44 0 0 25 0 1 0 65532932 487743488 116977 1283457024 134512640 135121179 4293579040 18446744073709551615 134839703 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/29561/statm: 119078 116977 329 149 0 118269 0 Current children cumulated CPU time (s) 282.1 Current children cumulated vsize (KiB) 478904 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.306 s] /proc/loadavg: 0.99 0.98 0.99 2/37 29565 /proc/meminfo: memFree=171428/1048576 swapFree=0/0 [pid=29552] ppid=29551 vsize=2592 CPUtime=1.82 /proc/29552/stat : 29552 (aspuncud-user-1) S 29551 29552 19908 34817 19908 4202496 571 14698 0 0 0 0 176 6 17 0 1 0 65532931 2654208 297 1283457024 134512640 135304128 4289674432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29552/statm: 648 297 251 194 0 35 0 [pid=29561] ppid=29552 vsize=480472 CPUtime=288.26 /proc/29561/stat : 29561 (unclasp) R 29552 29552 19908 34817 19908 4202496 128448 0 0 0 28778 48 0 0 25 0 1 0 65532932 492003328 118033 1283457024 134512640 135121179 4293579040 18446744073709551615 134836023 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/29561/statm: 120118 118033 329 149 0 119309 0 Current children cumulated CPU time (s) 290.08 Current children cumulated vsize (KiB) 483064 Sending User defined signal 1 to process tree (bottom up) Sleeping 10 seconds Solver just ended. Dumping a history of the last processes samples Child status: 0 Real time (s): 290.348 CPU time (s): 290.146 CPU user time (s): 289.558 CPU system time (s): 0.588036 CPU usage (%): 99.9306 Max. virtual memory (cumulated for all children) (KiB): 483808 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.558 system time used= 0.588036 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 146108 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= 97 involuntary context switches= 3581 runsolver used 0 second user time and 0 second system time The end