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/201012091704/aspcud-1.3/8ad21cec-4b22-11df-b280-00163e7a6f5e.cudf.debian-dudf.log.runsolver ./aspcud-1.3 /home/misc2010/data/2010/debian-dudf//8ad21cec-4b22-11df-b280-00163e7a6f5e.cudf /home/misc2010/tmp/201012091704/aspcud-1.3/8ad21cec-4b22-11df-b280-00163e7a6f5e.cudf.debian-dudf.result -changed,-notuptodate,-removed,-new 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.08 1.06 1.00 5/40 7937 /proc/meminfo: memFree=386548/1048576 swapFree=2095372/2097144 [pid=7935] ppid=7934 vsize=2584 CPUtime=0 /proc/7935/stat : 7935 (aspcud-1.3) S 7934 7935 25521 34816 2180 4202496 374 0 0 0 0 0 0 0 18 0 1 0 901800895 2646016 281 1283457024 134512640 135304128 4287711984 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/7935/statm: 646 281 237 194 0 32 0 [pid=7936] ppid=7935 vsize=2584 CPUtime=0 /proc/7936/stat : 7936 (aspcud-1.3) R 7935 7935 25521 34816 2180 4202560 105 0 0 0 0 0 0 0 25 0 1 0 901800896 2646016 127 1283457024 134512640 135304128 4287711984 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/7936/statm: 646 127 82 194 0 32 0 [pid=7937] ppid=7936 vsize=2584 CPUtime=0 /proc/7937/stat : 7937 (aspcud-1.3) R 7936 7935 25521 34816 2180 4202560 0 0 0 0 0 0 0 0 25 0 1 0 901800896 2646016 45 1283457024 134512640 135304128 4287711984 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/7937/statm: 646 45 0 194 0 32 0 [startup+0.172751 s] /proc/loadavg: 1.08 1.06 1.00 5/40 7937 /proc/meminfo: memFree=386548/1048576 swapFree=2095372/2097144 [pid=7935] ppid=7934 vsize=2592 CPUtime=0 /proc/7935/stat : 7935 (aspcud-1.3) S 7934 7935 25521 34816 2180 4202496 574 1506 0 0 0 0 0 0 25 0 1 0 901800895 2654208 299 1283457024 134512640 135304128 4287711984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7935/statm: 648 299 253 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.202772 s] /proc/loadavg: 1.08 1.06 1.00 5/40 7937 /proc/meminfo: memFree=386548/1048576 swapFree=2095372/2097144 [pid=7935] ppid=7934 vsize=2592 CPUtime=0 /proc/7935/stat : 7935 (aspcud-1.3) S 7934 7935 25521 34816 2180 4202496 574 1506 0 0 0 0 0 0 25 0 1 0 901800895 2654208 299 1283457024 134512640 135304128 4287711984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7935/statm: 648 299 253 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.312782 s] /proc/loadavg: 1.08 1.06 1.00 5/40 7937 /proc/meminfo: memFree=386548/1048576 swapFree=2095372/2097144 [pid=7935] ppid=7934 vsize=2592 CPUtime=0 /proc/7935/stat : 7935 (aspcud-1.3) S 7934 7935 25521 34816 2180 4202496 574 1506 0 0 0 0 0 0 25 0 1 0 901800895 2654208 299 1283457024 134512640 135304128 4287711984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7935/statm: 648 299 253 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.712864 s] /proc/loadavg: 1.08 1.06 1.00 5/40 7937 /proc/meminfo: memFree=386548/1048576 swapFree=2095372/2097144 [pid=7935] ppid=7934 vsize=2592 CPUtime=0 /proc/7935/stat : 7935 (aspcud-1.3) S 7934 7935 25521 34816 2180 4202496 574 1506 0 0 0 0 0 0 25 0 1 0 901800895 2654208 299 1283457024 134512640 135304128 4287711984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7935/statm: 648 299 253 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+1.51304 s] /proc/loadavg: 1.08 1.06 1.00 2/42 7946 /proc/meminfo: memFree=344608/1048576 swapFree=2095372/2097144 [pid=7935] ppid=7934 vsize=2592 CPUtime=0 /proc/7935/stat : 7935 (aspcud-1.3) S 7934 7935 25521 34816 2180 4202496 574 1506 0 0 0 0 0 0 25 0 1 0 901800895 2654208 299 1283457024 134512640 135304128 4287711984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7935/statm: 648 299 253 194 0 34 0 [pid=7944] ppid=7935 vsize=6312 CPUtime=0.02 /proc/7944/stat : 7944 (clasp) S 7935 7935 25521 34816 2180 4202496 1505 0 0 0 1 1 0 0 18 0 1 0 901800897 6463488 1292 1283457024 134512640 136223643 4292644800 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/7944/statm: 1578 1292 174 418 0 1158 0 [pid=7945] ppid=7935 vsize=9332 CPUtime=0.22 /proc/7945/stat : 7945 (gringo) R 7935 7935 25521 34816 2180 4202496 2450 0 0 0 19 3 0 0 18 0 1 0 901800897 9555968 1544 1283457024 134512640 136959103 4288232464 18446744073709551615 134620570 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7945/statm: 2333 1544 247 598 0 1732 0 [pid=7946] ppid=7935 vsize=40880 CPUtime=1.25 /proc/7946/stat : 7946 (cudf2lp) R 7935 7935 25521 34816 2180 4202496 13300 0 0 0 117 8 0 0 25 0 1 0 901800897 41861120 10031 1283457024 134512640 135749571 4294339040 18446744073709551615 135237662 0 0 6 0 0 0 0 17 0 0 0 0 /proc/7946/statm: 10220 10031 132 302 0 9916 0 Current children cumulated CPU time (s) 1.49 Current children cumulated vsize (KiB) 59116 [startup+3.11345 s] /proc/loadavg: 1.08 1.06 1.00 3/42 7946 /proc/meminfo: memFree=316088/1048576 swapFree=2095372/2097144 [pid=7935] ppid=7934 vsize=2592 CPUtime=1.49 /proc/7935/stat : 7935 (aspcud-1.3) S 7934 7935 25521 34816 2180 4202496 575 14809 0 0 0 0 137 12 18 0 1 0 901800895 2654208 299 1283457024 134512640 135304128 4287711984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7935/statm: 648 299 253 194 0 34 0 [pid=7944] ppid=7935 vsize=33152 CPUtime=0.19 /proc/7944/stat : 7944 (clasp) R 7935 7935 25521 34816 2180 4202496 9380 0 0 0 14 5 0 0 18 0 1 0 901800897 33947648 7881 1283457024 134512640 136223643 4292644800 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7944/statm: 8288 7881 174 418 0 7868 0 [pid=7945] ppid=7935 vsize=53456 CPUtime=1.41 /proc/7945/stat : 7945 (gringo) R 7935 7935 25521 34816 2180 4202496 15825 0 0 0 134 7 0 0 18 0 1 0 901800897 54738944 11065 1283457024 134512640 136959103 4288232464 18446744073709551615 135865785 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7945/statm: 13364 11065 256 598 0 12763 0 Current children cumulated CPU time (s) 3.09 Current children cumulated vsize (KiB) 89200 [startup+6.30782 s] /proc/loadavg: 1.08 1.06 1.00 2/40 7946 /proc/meminfo: memFree=332488/1048576 swapFree=2095372/2097144 [pid=7935] ppid=7934 vsize=2592 CPUtime=3.49 /proc/7935/stat : 7935 (aspcud-1.3) S 7934 7935 25521 34816 2180 4202496 575 33486 0 0 0 0 326 23 18 0 1 0 901800895 2654208 299 1283457024 134512640 135304128 4287711984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7935/statm: 648 299 253 194 0 34 0 [pid=7944] ppid=7935 vsize=58900 CPUtime=2.8 /proc/7944/stat : 7944 (clasp) R 7935 7935 25521 34816 2180 4202496 17163 0 0 0 273 7 0 0 22 0 1 0 901800897 60313600 13593 1283457024 134512640 136223643 4292644800 18446744073709551615 134712476 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7944/statm: 14725 13593 225 418 0 14305 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 61492 [startup+12.7103 s] /proc/loadavg: 1.07 1.06 1.00 2/40 7946 /proc/meminfo: memFree=321824/1048576 swapFree=2095372/2097144 [pid=7935] ppid=7934 vsize=2592 CPUtime=3.49 /proc/7935/stat : 7935 (aspcud-1.3) S 7934 7935 25521 34816 2180 4202496 575 33486 0 0 0 0 326 23 18 0 1 0 901800895 2654208 299 1283457024 134512640 135304128 4287711984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7935/statm: 648 299 253 194 0 34 0 [pid=7944] ppid=7935 vsize=72528 CPUtime=9.19 /proc/7944/stat : 7944 (clasp) R 7935 7935 25521 34816 2180 4202496 20563 0 0 0 911 8 0 0 25 0 1 0 901800897 74268672 16993 1283457024 134512640 136223643 4292644800 18446744073709551615 134711224 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7944/statm: 18132 16993 225 418 0 17712 0 Current children cumulated CPU time (s) 12.68 Current children cumulated vsize (KiB) 75120 [startup+25.5136 s] /proc/loadavg: 1.06 1.05 1.00 2/40 7946 /proc/meminfo: memFree=269372/1048576 swapFree=2095372/2097144 [pid=7935] ppid=7934 vsize=2592 CPUtime=3.49 /proc/7935/stat : 7935 (aspcud-1.3) S 7934 7935 25521 34816 2180 4202496 575 33486 0 0 0 0 326 23 18 0 1 0 901800895 2654208 299 1283457024 134512640 135304128 4287711984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7935/statm: 648 299 253 194 0 34 0 [pid=7944] ppid=7935 vsize=122256 CPUtime=21.97 /proc/7944/stat : 7944 (clasp) R 7935 7935 25521 34816 2180 4202496 33012 0 0 0 2185 12 0 0 25 0 1 0 901800897 125190144 29442 1283457024 134512640 136223643 4292644800 18446744073709551615 134928992 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7944/statm: 30564 29442 225 418 0 30144 0 Current children cumulated CPU time (s) 25.46 Current children cumulated vsize (KiB) 124848 [startup+51.1119 s] /proc/loadavg: 1.04 1.05 1.00 2/40 7946 /proc/meminfo: memFree=243580/1048576 swapFree=2095372/2097144 [pid=7935] ppid=7934 vsize=2592 CPUtime=3.49 /proc/7935/stat : 7935 (aspcud-1.3) S 7934 7935 25521 34816 2180 4202496 575 33486 0 0 0 0 326 23 18 0 1 0 901800895 2654208 299 1283457024 134512640 135304128 4287711984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7935/statm: 648 299 253 194 0 34 0 [pid=7944] ppid=7935 vsize=151052 CPUtime=47.54 /proc/7944/stat : 7944 (clasp) R 7935 7935 25521 34816 2180 4202496 40113 0 0 0 4741 13 0 0 25 0 1 0 901800897 154677248 36543 1283457024 134512640 136223643 4292644800 18446744073709551615 134711764 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7944/statm: 37763 36543 225 418 0 37343 0 Current children cumulated CPU time (s) 51.03 Current children cumulated vsize (KiB) 153644 [startup+102.308 s] /proc/loadavg: 1.01 1.04 1.00 2/40 7946 /proc/meminfo: memFree=234652/1048576 swapFree=2095372/2097144 [pid=7935] ppid=7934 vsize=2592 CPUtime=3.49 /proc/7935/stat : 7935 (aspcud-1.3) S 7934 7935 25521 34816 2180 4202496 575 33486 0 0 0 0 326 23 18 0 1 0 901800895 2654208 299 1283457024 134512640 135304128 4287711984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7935/statm: 648 299 253 194 0 34 0 [pid=7944] ppid=7935 vsize=157116 CPUtime=98.68 /proc/7944/stat : 7944 (clasp) R 7935 7935 25521 34816 2180 4202496 41641 0 0 0 9855 13 0 0 25 0 1 0 901800897 160886784 38071 1283457024 134512640 136223643 4292644800 18446744073709551615 134930980 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7944/statm: 39279 38071 225 418 0 38859 0 Current children cumulated CPU time (s) 102.17 Current children cumulated vsize (KiB) 159708 [startup+162.306 s] /proc/loadavg: 1.00 1.03 1.00 2/40 7946 /proc/meminfo: memFree=234280/1048576 swapFree=2095372/2097144 [pid=7935] ppid=7934 vsize=2592 CPUtime=3.49 /proc/7935/stat : 7935 (aspcud-1.3) S 7934 7935 25521 34816 2180 4202496 575 33486 0 0 0 0 326 23 18 0 1 0 901800895 2654208 299 1283457024 134512640 135304128 4287711984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7935/statm: 648 299 253 194 0 34 0 [pid=7944] ppid=7935 vsize=157116 CPUtime=158.62 /proc/7944/stat : 7944 (clasp) R 7935 7935 25521 34816 2180 4202496 41708 0 0 0 15848 14 0 0 25 0 1 0 901800897 160886784 38138 1283457024 134512640 136223643 4292644800 18446744073709551615 134929292 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7944/statm: 39279 38138 225 418 0 38859 0 Current children cumulated CPU time (s) 162.11 Current children cumulated vsize (KiB) 159708 [startup+222.314 s] /proc/loadavg: 1.00 1.02 1.00 2/40 7946 /proc/meminfo: memFree=234156/1048576 swapFree=2095372/2097144 [pid=7935] ppid=7934 vsize=2592 CPUtime=3.49 /proc/7935/stat : 7935 (aspcud-1.3) S 7934 7935 25521 34816 2180 4202496 575 33486 0 0 0 0 326 23 18 0 1 0 901800895 2654208 299 1283457024 134512640 135304128 4287711984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7935/statm: 648 299 253 194 0 34 0 [pid=7944] ppid=7935 vsize=157116 CPUtime=218.58 /proc/7944/stat : 7944 (clasp) R 7935 7935 25521 34816 2180 4202496 41711 0 0 0 21844 14 0 0 25 0 1 0 901800897 160886784 38141 1283457024 134512640 136223643 4292644800 18446744073709551615 134930961 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7944/statm: 39279 38141 225 418 0 38859 0 Current children cumulated CPU time (s) 222.07 Current children cumulated vsize (KiB) 159708 [startup+282.314 s] /proc/loadavg: 1.00 1.02 1.00 2/40 7946 /proc/meminfo: memFree=217168/1048576 swapFree=2095372/2097144 [pid=7935] ppid=7934 vsize=2592 CPUtime=3.49 /proc/7935/stat : 7935 (aspcud-1.3) S 7934 7935 25521 34816 2180 4202496 575 33486 0 0 0 0 326 23 18 0 1 0 901800895 2654208 299 1283457024 134512640 135304128 4287711984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7935/statm: 648 299 253 194 0 34 0 [pid=7944] ppid=7935 vsize=174184 CPUtime=278.54 /proc/7944/stat : 7944 (clasp) R 7935 7935 25521 34816 2180 4202496 45952 0 0 0 27834 20 0 0 25 0 1 0 901800897 178364416 42382 1283457024 134512640 136223643 4292644800 18446744073709551615 134931000 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7944/statm: 43546 42382 225 418 0 43126 0 Current children cumulated CPU time (s) 282.03 Current children cumulated vsize (KiB) 176776 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.306 s] /proc/loadavg: 1.00 1.01 1.00 2/40 7946 /proc/meminfo: memFree=217168/1048576 swapFree=2095372/2097144 [pid=7935] ppid=7934 vsize=2592 CPUtime=3.49 /proc/7935/stat : 7935 (aspcud-1.3) S 7934 7935 25521 34816 2180 4202496 575 33486 0 0 0 0 326 23 18 0 1 0 901800895 2654208 299 1283457024 134512640 135304128 4287711984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7935/statm: 648 299 253 194 0 34 0 [pid=7944] ppid=7935 vsize=174184 CPUtime=286.53 /proc/7944/stat : 7944 (clasp) R 7935 7935 25521 34816 2180 4202496 45956 0 0 0 28633 20 0 0 25 0 1 0 901800897 178364416 42386 1283457024 134512640 136223643 4292644800 18446744073709551615 134928913 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7944/statm: 43546 42386 225 418 0 43126 0 Current children cumulated CPU time (s) 290.02 Current children cumulated vsize (KiB) 176776 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.341 CPU time (s): 290.074 CPU user time (s): 289.602 CPU system time (s): 0.472029 CPU usage (%): 99.908 Max. virtual memory (cumulated for all children) (KiB): 176776 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.602 system time used= 0.472029 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 82647 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= 2948 involuntary context switches= 5958 runsolver used 0 second user time and 0.008 second system time The end