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/aspcud-1.5/56ae4afa-0b33-11df-8a2b-00163e1d94dc.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//56ae4afa-0b33-11df-8a2b-00163e1d94dc.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/56ae4afa-0b33-11df-8a2b-00163e1d94dc.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.92 1.01 0.99 5/35 28946 /proc/meminfo: memFree=749184/1048576 swapFree=0/0 [pid=28944] ppid=28943 vsize=2584 CPUtime=0 /proc/28944/stat : 28944 (aspcud-1.5) S 28943 28944 19908 34817 19908 4202496 373 0 0 0 0 0 0 0 18 0 1 0 65182135 2646016 279 1283457024 134512640 135304128 4289871120 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/28944/statm: 646 279 234 194 0 33 0 [pid=28945] ppid=28944 vsize=2584 CPUtime=0 /proc/28945/stat : 28945 (aspcud-1.5) R 28944 28944 19908 34817 19908 4202560 110 0 0 0 0 0 0 0 25 0 1 0 65182135 2646016 132 1283457024 134512640 135304128 4289871120 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/28945/statm: 646 132 86 194 0 33 0 [pid=28946] ppid=28945 vsize=2584 CPUtime=0 /proc/28946/stat : 28946 (aspcud-1.5) R 28945 28944 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 65182136 2646016 46 1283457024 134512640 135304128 4289871120 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/28946/statm: 646 46 0 194 0 33 0 [startup+0.134357 s] /proc/loadavg: 0.92 1.01 0.99 5/35 28946 /proc/meminfo: memFree=749184/1048576 swapFree=0/0 [pid=28944] ppid=28943 vsize=2592 CPUtime=0.01 /proc/28944/stat : 28944 (aspcud-1.5) S 28943 28944 19908 34817 19908 4202496 579 1521 0 0 1 0 0 0 25 0 1 0 65182135 2654208 298 1283457024 134512640 135304128 4289871120 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28944/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.2129 s] /proc/loadavg: 0.92 1.01 0.99 5/35 28946 /proc/meminfo: memFree=749184/1048576 swapFree=0/0 [pid=28944] ppid=28943 vsize=2592 CPUtime=0.01 /proc/28944/stat : 28944 (aspcud-1.5) S 28943 28944 19908 34817 19908 4202496 579 1521 0 0 1 0 0 0 25 0 1 0 65182135 2654208 298 1283457024 134512640 135304128 4289871120 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28944/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.303113 s] /proc/loadavg: 0.92 1.01 0.99 5/35 28946 /proc/meminfo: memFree=749184/1048576 swapFree=0/0 [pid=28944] ppid=28943 vsize=2592 CPUtime=0.01 /proc/28944/stat : 28944 (aspcud-1.5) S 28943 28944 19908 34817 19908 4202496 579 1521 0 0 1 0 0 0 25 0 1 0 65182135 2654208 298 1283457024 134512640 135304128 4289871120 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28944/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.706416 s] /proc/loadavg: 0.92 1.01 0.99 5/35 28946 /proc/meminfo: memFree=749184/1048576 swapFree=0/0 [pid=28944] ppid=28943 vsize=2592 CPUtime=0.01 /proc/28944/stat : 28944 (aspcud-1.5) S 28943 28944 19908 34817 19908 4202496 579 1521 0 0 1 0 0 0 25 0 1 0 65182135 2654208 298 1283457024 134512640 135304128 4289871120 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28944/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+1.50647 s] /proc/loadavg: 0.92 1.01 0.99 2/37 28955 /proc/meminfo: memFree=713796/1048576 swapFree=0/0 [pid=28944] ppid=28943 vsize=2592 CPUtime=0.01 /proc/28944/stat : 28944 (aspcud-1.5) S 28943 28944 19908 34817 19908 4202496 579 1521 0 0 1 0 0 0 25 0 1 0 65182135 2654208 298 1283457024 134512640 135304128 4289871120 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28944/statm: 648 298 251 194 0 35 0 [pid=28953] ppid=28944 vsize=1924 CPUtime=0 /proc/28953/stat : 28953 (clasp) S 28944 28944 19908 34817 19908 4202496 291 0 0 0 0 0 0 0 25 0 1 0 65182136 1970176 159 1283457024 134512640 136285277 4291292800 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/28953/statm: 481 159 144 433 0 46 0 [pid=28954] ppid=28944 vsize=2584 CPUtime=0 /proc/28954/stat : 28954 (gringo) S 28944 28944 19908 34817 19908 4202496 404 0 0 0 0 0 0 0 25 0 1 0 65182136 2646016 272 1283457024 134512640 136933539 4286810800 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/28954/statm: 646 272 242 592 0 51 0 [pid=28955] ppid=28944 vsize=26168 CPUtime=1.17 /proc/28955/stat : 28955 (cudf2lp) R 28944 28944 19908 34817 19908 4202496 7610 0 0 0 116 1 0 0 25 0 1 0 65182137 26796032 6012 1283457024 134512640 135786343 4294195648 18446744073709551615 134764332 0 0 6 0 0 0 0 17 0 0 0 0 /proc/28955/statm: 6542 6012 128 311 0 6229 0 Current children cumulated CPU time (s) 1.18 Current children cumulated vsize (KiB) 33268 [startup+3.10739 s] /proc/loadavg: 0.92 1.01 0.99 2/37 28955 /proc/meminfo: memFree=680772/1048576 swapFree=0/0 [pid=28944] ppid=28943 vsize=2592 CPUtime=2.17 /proc/28944/stat : 28944 (aspcud-1.5) R 28943 28944 19908 34817 19908 4202496 579 17560 0 0 1 0 210 6 19 0 1 0 65182135 2654208 298 1283457024 134512640 135304128 4289871120 18446744073709551615 4294960130 0 65536 4 1132560123 0 0 0 17 0 0 0 0 /proc/28944/statm: 648 298 251 194 0 35 0 [pid=28953] ppid=28944 vsize=5408 CPUtime=0.43 /proc/28953/stat : 28953 (clasp) R 28944 28944 19908 34817 19908 4202496 1256 0 0 0 42 1 0 0 18 0 1 0 65182136 5537792 1121 1283457024 134512640 136285277 4291292800 18446744073709551615 134734279 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/28953/statm: 1352 1121 234 433 0 917 0 [pid=28954] ppid=28944 vsize=0 CPUtime=0.11 /proc/28954/stat : 28954 (gringo) Z 28944 28944 19908 34817 19908 4202508 1442 0 0 0 11 0 0 0 18 0 1 0 65182136 0 0 1283457024 0 0 0 0 0 0 0 6 16384 18446744071564254338 0 0 17 0 0 0 0 /proc/28954/statm: 0 0 0 0 0 0 0 Current children cumulated CPU time (s) 2.71 Current children cumulated vsize (KiB) 8000 [startup+6.30813 s] /proc/loadavg: 0.93 1.00 0.99 2/35 28955 /proc/meminfo: memFree=723096/1048576 swapFree=0/0 [pid=28944] ppid=28943 vsize=2592 CPUtime=2.29 /proc/28944/stat : 28944 (aspcud-1.5) S 28943 28944 19908 34817 19908 4202496 579 19002 0 0 1 0 222 6 16 0 1 0 65182135 2654208 298 1283457024 134512640 135304128 4289871120 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28944/statm: 648 298 251 194 0 35 0 [pid=28953] ppid=28944 vsize=6444 CPUtime=3.62 /proc/28953/stat : 28953 (clasp) R 28944 28944 19908 34817 19908 4202496 1534 0 0 0 361 1 0 0 25 0 1 0 65182136 6598656 1399 1283457024 134512640 136285277 4291292800 18446744073709551615 134985081 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/28953/statm: 1611 1399 234 433 0 1176 0 Current children cumulated CPU time (s) 5.91 Current children cumulated vsize (KiB) 9036 [startup+12.7095 s] /proc/loadavg: 0.94 1.00 0.99 2/35 28955 /proc/meminfo: memFree=721732/1048576 swapFree=0/0 [pid=28944] ppid=28943 vsize=2592 CPUtime=2.29 /proc/28944/stat : 28944 (aspcud-1.5) S 28943 28944 19908 34817 19908 4202496 579 19002 0 0 1 0 222 6 16 0 1 0 65182135 2654208 298 1283457024 134512640 135304128 4289871120 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28944/statm: 648 298 251 194 0 35 0 [pid=28953] ppid=28944 vsize=6992 CPUtime=10.02 /proc/28953/stat : 28953 (clasp) R 28944 28944 19908 34817 19908 4202496 1707 0 0 0 1001 1 0 0 25 0 1 0 65182136 7159808 1543 1283457024 134512640 136285277 4291292800 18446744073709551615 134649408 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/28953/statm: 1748 1543 234 433 0 1313 0 Current children cumulated CPU time (s) 12.31 Current children cumulated vsize (KiB) 9584 [startup+25.5119 s] /proc/loadavg: 0.95 1.00 0.99 2/35 28955 /proc/meminfo: memFree=721112/1048576 swapFree=0/0 [pid=28944] ppid=28943 vsize=2592 CPUtime=2.29 /proc/28944/stat : 28944 (aspcud-1.5) S 28943 28944 19908 34817 19908 4202496 579 19002 0 0 1 0 222 6 16 0 1 0 65182135 2654208 298 1283457024 134512640 135304128 4289871120 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28944/statm: 648 298 251 194 0 35 0 [pid=28953] ppid=28944 vsize=7560 CPUtime=22.82 /proc/28953/stat : 28953 (clasp) R 28944 28944 19908 34817 19908 4202496 1880 0 0 0 2281 1 0 0 25 0 1 0 65182136 7741440 1679 1283457024 134512640 136285277 4291292800 18446744073709551615 134723291 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/28953/statm: 1890 1679 234 433 0 1455 0 Current children cumulated CPU time (s) 25.11 Current children cumulated vsize (KiB) 10152 [startup+51.107 s] /proc/loadavg: 0.97 1.00 0.99 2/35 28955 /proc/meminfo: memFree=720740/1048576 swapFree=0/0 [pid=28944] ppid=28943 vsize=2592 CPUtime=2.29 /proc/28944/stat : 28944 (aspcud-1.5) S 28943 28944 19908 34817 19908 4202496 579 19002 0 0 1 0 222 6 16 0 1 0 65182135 2654208 298 1283457024 134512640 135304128 4289871120 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28944/statm: 648 298 251 194 0 35 0 [pid=28953] ppid=28944 vsize=7928 CPUtime=48.4 /proc/28953/stat : 28953 (clasp) R 28944 28944 19908 34817 19908 4202496 2035 0 0 0 4838 2 0 0 25 0 1 0 65182136 8118272 1776 1283457024 134512640 136285277 4291292800 18446744073709551615 134733725 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/28953/statm: 1982 1776 234 433 0 1547 0 Current children cumulated CPU time (s) 50.69 Current children cumulated vsize (KiB) 10520 [startup+102.308 s] /proc/loadavg: 0.98 1.00 0.99 2/35 28955 /proc/meminfo: memFree=720120/1048576 swapFree=0/0 [pid=28944] ppid=28943 vsize=2592 CPUtime=2.29 /proc/28944/stat : 28944 (aspcud-1.5) S 28943 28944 19908 34817 19908 4202496 579 19002 0 0 1 0 222 6 16 0 1 0 65182135 2654208 298 1283457024 134512640 135304128 4289871120 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28944/statm: 648 298 251 194 0 35 0 [pid=28953] ppid=28944 vsize=8568 CPUtime=99.58 /proc/28953/stat : 28953 (clasp) R 28944 28944 19908 34817 19908 4202496 2202 0 0 0 9956 2 0 0 25 0 1 0 65182136 8773632 1916 1283457024 134512640 136285277 4291292800 18446744073709551615 134735672 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/28953/statm: 2142 1916 234 433 0 1707 0 Current children cumulated CPU time (s) 101.87 Current children cumulated vsize (KiB) 11160 [startup+162.31 s] /proc/loadavg: 0.99 1.00 0.99 2/35 28955 /proc/meminfo: memFree=720120/1048576 swapFree=0/0 [pid=28944] ppid=28943 vsize=2592 CPUtime=2.29 /proc/28944/stat : 28944 (aspcud-1.5) S 28943 28944 19908 34817 19908 4202496 579 19002 0 0 1 0 222 6 16 0 1 0 65182135 2654208 298 1283457024 134512640 135304128 4289871120 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28944/statm: 648 298 251 194 0 35 0 [pid=28953] ppid=28944 vsize=8452 CPUtime=159.55 /proc/28953/stat : 28953 (clasp) R 28944 28944 19908 34817 19908 4202496 2202 0 0 0 15953 2 0 0 25 0 1 0 65182136 8654848 1905 1283457024 134512640 136285277 4291292800 18446744073709551615 134686305 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/28953/statm: 2113 1905 234 433 0 1678 0 Current children cumulated CPU time (s) 161.84 Current children cumulated vsize (KiB) 11044 [startup+222.312 s] /proc/loadavg: 0.99 1.00 0.99 2/37 28960 /proc/meminfo: memFree=719972/1048576 swapFree=0/0 [pid=28944] ppid=28943 vsize=2592 CPUtime=2.29 /proc/28944/stat : 28944 (aspcud-1.5) S 28943 28944 19908 34817 19908 4202496 579 19002 0 0 1 0 222 6 16 0 1 0 65182135 2654208 298 1283457024 134512640 135304128 4289871120 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28944/statm: 648 298 251 194 0 35 0 [pid=28953] ppid=28944 vsize=8452 CPUtime=219.52 /proc/28953/stat : 28953 (clasp) R 28944 28944 19908 34817 19908 4202496 2202 0 0 0 21950 2 0 0 25 0 1 0 65182136 8654848 1905 1283457024 134512640 136285277 4291292800 18446744073709551615 134963464 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/28953/statm: 2113 1905 234 433 0 1678 0 Current children cumulated CPU time (s) 221.81 Current children cumulated vsize (KiB) 11044 [startup+282.305 s] /proc/loadavg: 0.99 1.00 0.99 2/37 28966 /proc/meminfo: memFree=719724/1048576 swapFree=0/0 [pid=28944] ppid=28943 vsize=2592 CPUtime=2.29 /proc/28944/stat : 28944 (aspcud-1.5) S 28943 28944 19908 34817 19908 4202496 579 19002 0 0 1 0 222 6 16 0 1 0 65182135 2654208 298 1283457024 134512640 135304128 4289871120 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28944/statm: 648 298 251 194 0 35 0 [pid=28953] ppid=28944 vsize=8604 CPUtime=279.48 /proc/28953/stat : 28953 (clasp) R 28944 28944 19908 34817 19908 4202496 2236 0 0 0 27945 3 0 0 25 0 1 0 65182136 8810496 1939 1283457024 134512640 136285277 4291292800 18446744073709551615 134735727 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/28953/statm: 2151 1939 234 433 0 1716 0 Current children cumulated CPU time (s) 281.77 Current children cumulated vsize (KiB) 11196 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.607 s] /proc/loadavg: 0.99 1.00 0.99 2/36 28966 /proc/meminfo: memFree=719740/1048576 swapFree=0/0 [pid=28944] ppid=28943 vsize=2592 CPUtime=2.29 /proc/28944/stat : 28944 (aspcud-1.5) S 28943 28944 19908 34817 19908 4202496 579 19002 0 0 1 0 222 6 16 0 1 0 65182135 2654208 298 1283457024 134512640 135304128 4289871120 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28944/statm: 648 298 251 194 0 35 0 [pid=28953] ppid=28944 vsize=8776 CPUtime=287.78 /proc/28953/stat : 28953 (clasp) R 28944 28944 19908 34817 19908 4202496 2246 0 0 0 28775 3 0 0 25 0 1 0 65182136 8986624 1949 1283457024 134512640 136285277 4291292800 18446744073709551615 134959946 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/28953/statm: 2194 1949 234 433 0 1759 0 Current children cumulated CPU time (s) 290.07 Current children cumulated vsize (KiB) 11368 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.607 s] /proc/loadavg: 0.99 1.00 0.99 2/36 28966 /proc/meminfo: memFree=719740/1048576 swapFree=0/0 [pid=28944] ppid=28943 vsize=2592 CPUtime=2.29 /proc/28944/stat : 28944 (aspcud-1.5) S 28943 28944 19908 34817 19908 4202496 579 19002 0 0 1 0 222 6 16 0 1 0 65182135 2654208 298 1283457024 134512640 135304128 4289871120 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28944/statm: 648 298 251 194 0 35 0 [pid=28953] ppid=28944 vsize=8776 CPUtime=287.78 /proc/28953/stat : 28953 (clasp) R 28944 28944 19908 34817 19908 4202496 2246 0 0 0 28775 3 0 0 25 0 1 0 65182136 8986624 1949 1283457024 134512640 136285277 4291292800 18446744073709551615 134959946 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/28953/statm: 2194 1949 234 433 0 1759 0 Current children cumulated CPU time (s) 290.07 Current children cumulated vsize (KiB) 11368 Child status: 0 Real time (s): 290.627 CPU time (s): 290.098 CPU user time (s): 290.006 CPU system time (s): 0.092005 CPU usage (%): 99.8179 Max. virtual memory (cumulated for all children) (KiB): 65300 getrusage(RUSAGE_CHILDREN,...) data: user time used= 290.006 system time used= 0.092005 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 25369 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= 236 involuntary context switches= 3781 runsolver used 0 second user time and 0 second system time The end