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/rand933.cudf.dudf-random.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-random//rand933.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/rand933.cudf.dudf-random.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.06 1.10 1.04 4/34 29296 /proc/meminfo: memFree=694272/1048576 swapFree=0/0 [pid=29294] ppid=29293 vsize=2588 CPUtime=0 /proc/29294/stat : 29294 (aspcud-1.5) S 29293 29294 19908 34817 19908 4202496 373 0 0 0 0 0 0 0 18 0 1 0 65386858 2650112 279 1283457024 134512640 135304128 4294023488 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/29294/statm: 647 279 234 194 0 34 0 [pid=29295] ppid=29294 vsize=2588 CPUtime=0 /proc/29295/stat : 29295 (aspcud-1.5) R 29294 29294 19908 34817 19908 4202560 110 0 0 0 0 0 0 0 25 0 1 0 65386858 2650112 132 1283457024 134512640 135304128 4294023488 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/29295/statm: 647 132 86 194 0 34 0 [startup+0.110216 s] /proc/loadavg: 1.06 1.10 1.04 4/34 29296 /proc/meminfo: memFree=694272/1048576 swapFree=0/0 [pid=29294] ppid=29293 vsize=2596 CPUtime=0 /proc/29294/stat : 29294 (aspcud-1.5) S 29293 29294 19908 34817 19908 4202496 580 1520 0 0 0 0 0 0 25 0 1 0 65386858 2658304 298 1283457024 134512640 135304128 4294023488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29294/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.206231 s] /proc/loadavg: 1.06 1.10 1.04 4/34 29296 /proc/meminfo: memFree=694272/1048576 swapFree=0/0 [pid=29294] ppid=29293 vsize=2596 CPUtime=0 /proc/29294/stat : 29294 (aspcud-1.5) S 29293 29294 19908 34817 19908 4202496 580 1520 0 0 0 0 0 0 25 0 1 0 65386858 2658304 298 1283457024 134512640 135304128 4294023488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29294/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.306232 s] /proc/loadavg: 1.06 1.10 1.04 4/34 29296 /proc/meminfo: memFree=694272/1048576 swapFree=0/0 [pid=29294] ppid=29293 vsize=2596 CPUtime=0 /proc/29294/stat : 29294 (aspcud-1.5) S 29293 29294 19908 34817 19908 4202496 580 1520 0 0 0 0 0 0 25 0 1 0 65386858 2658304 298 1283457024 134512640 135304128 4294023488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29294/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.706255 s] /proc/loadavg: 1.06 1.10 1.04 4/34 29296 /proc/meminfo: memFree=694272/1048576 swapFree=0/0 [pid=29294] ppid=29293 vsize=2596 CPUtime=0 /proc/29294/stat : 29294 (aspcud-1.5) S 29293 29294 19908 34817 19908 4202496 580 1520 0 0 0 0 0 0 25 0 1 0 65386858 2658304 298 1283457024 134512640 135304128 4294023488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29294/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50632 s] /proc/loadavg: 1.06 1.10 1.04 2/37 29305 /proc/meminfo: memFree=652604/1048576 swapFree=0/0 [pid=29294] ppid=29293 vsize=2596 CPUtime=0 /proc/29294/stat : 29294 (aspcud-1.5) S 29293 29294 19908 34817 19908 4202496 580 1520 0 0 0 0 0 0 25 0 1 0 65386858 2658304 298 1283457024 134512640 135304128 4294023488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29294/statm: 649 298 251 194 0 36 0 [pid=29303] ppid=29294 vsize=1932 CPUtime=0 /proc/29303/stat : 29303 (clasp) S 29294 29294 19908 34817 19908 4202496 293 0 0 0 0 0 0 0 25 0 1 0 65386859 1978368 160 1283457024 134512640 136285277 4287455952 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/29303/statm: 483 160 144 433 0 48 0 [pid=29304] ppid=29294 vsize=2584 CPUtime=0 /proc/29304/stat : 29304 (gringo) S 29294 29294 19908 34817 19908 4202496 405 0 0 0 0 0 0 0 25 0 1 0 65386859 2646016 272 1283457024 134512640 136933539 4287845296 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/29304/statm: 646 272 242 592 0 51 0 [pid=29305] ppid=29294 vsize=27480 CPUtime=1.3 /proc/29305/stat : 29305 (cudf2lp) R 29294 29294 19908 34817 19908 4202496 7683 0 0 0 128 2 0 0 25 0 1 0 65386859 28139520 6181 1283457024 134512640 135786343 4288257056 18446744073709551615 135208400 0 0 6 0 0 0 0 17 0 0 0 0 /proc/29305/statm: 6870 6181 128 311 0 6557 0 Current children cumulated CPU time (s) 1.3 Current children cumulated vsize (KiB) 34592 [startup+3.10792 s] /proc/loadavg: 1.06 1.10 1.04 2/37 29305 /proc/meminfo: memFree=619528/1048576 swapFree=0/0 [pid=29294] ppid=29293 vsize=2596 CPUtime=2.14 /proc/29294/stat : 29294 (aspcud-1.5) R 29293 29294 19908 34817 19908 4202496 580 15026 0 0 0 0 210 4 19 0 1 0 65386858 2658304 298 1283457024 134512640 135304128 4294023488 18446744073709551615 4294960130 0 65536 4 1132560123 0 0 0 17 0 0 0 0 /proc/29294/statm: 649 298 251 194 0 36 0 [pid=29303] ppid=29294 vsize=4828 CPUtime=0.59 /proc/29303/stat : 29303 (clasp) R 29294 29294 19908 34817 19908 4202496 1126 0 0 0 59 0 0 0 18 0 1 0 65386859 4943872 993 1283457024 134512640 136285277 4287455952 18446744073709551615 134959659 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29303/statm: 1207 993 234 433 0 772 0 [pid=29304] ppid=29294 vsize=0 CPUtime=0.09 /proc/29304/stat : 29304 (gringo) Z 29294 29294 19908 34817 19908 4202508 1282 0 0 0 9 0 0 0 18 0 1 0 65386859 0 0 1283457024 0 0 0 0 0 0 0 6 16384 18446744071564254338 0 0 17 0 0 0 0 /proc/29304/statm: 0 0 0 0 0 0 0 Current children cumulated CPU time (s) 2.82 Current children cumulated vsize (KiB) 7424 [startup+6.30848 s] /proc/loadavg: 1.05 1.10 1.04 2/35 29305 /proc/meminfo: memFree=662464/1048576 swapFree=0/0 [pid=29294] ppid=29293 vsize=2596 CPUtime=2.23 /proc/29294/stat : 29294 (aspcud-1.5) S 29293 29294 19908 34817 19908 4202496 580 16308 0 0 0 0 219 4 16 0 1 0 65386858 2658304 298 1283457024 134512640 135304128 4294023488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29294/statm: 649 298 251 194 0 36 0 [pid=29303] ppid=29294 vsize=6368 CPUtime=3.78 /proc/29303/stat : 29303 (clasp) R 29294 29294 19908 34817 19908 4202496 1515 0 0 0 378 0 0 0 25 0 1 0 65386859 6520832 1382 1283457024 134512640 136285277 4287455952 18446744073709551615 134963464 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29303/statm: 1592 1382 234 433 0 1157 0 Current children cumulated CPU time (s) 6.01 Current children cumulated vsize (KiB) 8964 [startup+12.7099 s] /proc/loadavg: 1.05 1.10 1.04 2/35 29305 /proc/meminfo: memFree=661604/1048576 swapFree=0/0 [pid=29294] ppid=29293 vsize=2596 CPUtime=2.23 /proc/29294/stat : 29294 (aspcud-1.5) S 29293 29294 19908 34817 19908 4202496 580 16308 0 0 0 0 219 4 16 0 1 0 65386858 2658304 298 1283457024 134512640 135304128 4294023488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29294/statm: 649 298 251 194 0 36 0 [pid=29303] ppid=29294 vsize=7080 CPUtime=10.18 /proc/29303/stat : 29303 (clasp) R 29294 29294 19908 34817 19908 4202496 1689 0 0 0 1018 0 0 0 25 0 1 0 65386859 7249920 1556 1283457024 134512640 136285277 4287455952 18446744073709551615 134669900 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29303/statm: 1770 1556 234 433 0 1335 0 Current children cumulated CPU time (s) 12.41 Current children cumulated vsize (KiB) 9676 [startup+25.513 s] /proc/loadavg: 1.04 1.09 1.04 2/35 29305 /proc/meminfo: memFree=660984/1048576 swapFree=0/0 [pid=29294] ppid=29293 vsize=2596 CPUtime=2.23 /proc/29294/stat : 29294 (aspcud-1.5) S 29293 29294 19908 34817 19908 4202496 580 16308 0 0 0 0 219 4 16 0 1 0 65386858 2658304 298 1283457024 134512640 135304128 4294023488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29294/statm: 649 298 251 194 0 36 0 [pid=29303] ppid=29294 vsize=7532 CPUtime=22.98 /proc/29303/stat : 29303 (clasp) R 29294 29294 19908 34817 19908 4202496 1819 0 0 0 2298 0 0 0 25 0 1 0 65386859 7712768 1665 1283457024 134512640 136285277 4287455952 18446744073709551615 134960068 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29303/statm: 1883 1665 234 433 0 1448 0 Current children cumulated CPU time (s) 25.21 Current children cumulated vsize (KiB) 10128 [startup+51.1083 s] /proc/loadavg: 1.02 1.08 1.03 2/35 29305 /proc/meminfo: memFree=659992/1048576 swapFree=0/0 [pid=29294] ppid=29293 vsize=2596 CPUtime=2.23 /proc/29294/stat : 29294 (aspcud-1.5) S 29293 29294 19908 34817 19908 4202496 580 16308 0 0 0 0 219 4 16 0 1 0 65386858 2658304 298 1283457024 134512640 135304128 4294023488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29294/statm: 649 298 251 194 0 36 0 [pid=29303] ppid=29294 vsize=8380 CPUtime=48.56 /proc/29303/stat : 29303 (clasp) R 29294 29294 19908 34817 19908 4202496 2062 0 0 0 4856 0 0 0 25 0 1 0 65386859 8581120 1890 1283457024 134512640 136285277 4287455952 18446744073709551615 134723291 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29303/statm: 2095 1890 234 433 0 1660 0 Current children cumulated CPU time (s) 50.79 Current children cumulated vsize (KiB) 10976 [startup+102.308 s] /proc/loadavg: 1.01 1.07 1.03 2/35 29305 /proc/meminfo: memFree=659248/1048576 swapFree=0/0 [pid=29294] ppid=29293 vsize=2596 CPUtime=2.23 /proc/29294/stat : 29294 (aspcud-1.5) S 29293 29294 19908 34817 19908 4202496 580 16308 0 0 0 0 219 4 16 0 1 0 65386858 2658304 298 1283457024 134512640 135304128 4294023488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29294/statm: 649 298 251 194 0 36 0 [pid=29303] ppid=29294 vsize=9424 CPUtime=99.78 /proc/29303/stat : 29303 (clasp) R 29294 29294 19908 34817 19908 4202496 2348 0 0 0 9978 0 0 0 25 0 1 0 65386859 9650176 2130 1283457024 134512640 136285277 4287455952 18446744073709551615 134669863 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29303/statm: 2356 2130 234 433 0 1921 0 Current children cumulated CPU time (s) 102.01 Current children cumulated vsize (KiB) 12020 [startup+162.314 s] /proc/loadavg: 1.00 1.05 1.02 2/37 29308 /proc/meminfo: memFree=658356/1048576 swapFree=0/0 [pid=29294] ppid=29293 vsize=2596 CPUtime=2.23 /proc/29294/stat : 29294 (aspcud-1.5) S 29293 29294 19908 34817 19908 4202496 580 16308 0 0 0 0 219 4 16 0 1 0 65386858 2658304 298 1283457024 134512640 135304128 4294023488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29294/statm: 649 298 251 194 0 36 0 [pid=29303] ppid=29294 vsize=9828 CPUtime=159.75 /proc/29303/stat : 29303 (clasp) R 29294 29294 19908 34817 19908 4202496 2539 0 0 0 15975 0 0 0 25 0 1 0 65386859 10063872 2245 1283457024 134512640 136285277 4287455952 18446744073709551615 134733722 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29303/statm: 2457 2245 234 433 0 2022 0 Current children cumulated CPU time (s) 161.98 Current children cumulated vsize (KiB) 12424 [startup+222.307 s] /proc/loadavg: 1.00 1.04 1.02 2/37 29314 /proc/meminfo: memFree=657240/1048576 swapFree=0/0 [pid=29294] ppid=29293 vsize=2596 CPUtime=2.23 /proc/29294/stat : 29294 (aspcud-1.5) S 29293 29294 19908 34817 19908 4202496 580 16308 0 0 0 0 219 4 16 0 1 0 65386858 2658304 298 1283457024 134512640 135304128 4294023488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29294/statm: 649 298 251 194 0 36 0 [pid=29303] ppid=29294 vsize=11008 CPUtime=219.7 /proc/29303/stat : 29303 (clasp) R 29294 29294 19908 34817 19908 4202496 2882 0 0 0 21970 0 0 0 25 0 1 0 65386859 11272192 2544 1283457024 134512640 136285277 4287455952 18446744073709551615 134955224 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29303/statm: 2752 2544 234 433 0 2317 0 Current children cumulated CPU time (s) 221.93 Current children cumulated vsize (KiB) 13604 [startup+282.308 s] /proc/loadavg: 1.00 1.03 1.01 2/36 29316 /proc/meminfo: memFree=657132/1048576 swapFree=0/0 [pid=29294] ppid=29293 vsize=2596 CPUtime=2.23 /proc/29294/stat : 29294 (aspcud-1.5) S 29293 29294 19908 34817 19908 4202496 580 16308 0 0 0 0 219 4 16 0 1 0 65386858 2658304 298 1283457024 134512640 135304128 4294023488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29294/statm: 649 298 251 194 0 36 0 [pid=29303] ppid=29294 vsize=11008 CPUtime=279.66 /proc/29303/stat : 29303 (clasp) R 29294 29294 19908 34817 19908 4202496 2882 0 0 0 27966 0 0 0 25 0 1 0 65386859 11272192 2544 1283457024 134512640 136285277 4287455952 18446744073709551615 134960063 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29303/statm: 2752 2544 234 433 0 2317 0 Current children cumulated CPU time (s) 281.89 Current children cumulated vsize (KiB) 13604 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.51 s] /proc/loadavg: 1.00 1.03 1.01 2/36 29316 /proc/meminfo: memFree=657132/1048576 swapFree=0/0 [pid=29294] ppid=29293 vsize=2596 CPUtime=2.23 /proc/29294/stat : 29294 (aspcud-1.5) S 29293 29294 19908 34817 19908 4202496 580 16308 0 0 0 0 219 4 16 0 1 0 65386858 2658304 298 1283457024 134512640 135304128 4294023488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29294/statm: 649 298 251 194 0 36 0 [pid=29303] ppid=29294 vsize=11008 CPUtime=287.86 /proc/29303/stat : 29303 (clasp) R 29294 29294 19908 34817 19908 4202496 2882 0 0 0 28786 0 0 0 25 0 1 0 65386859 11272192 2544 1283457024 134512640 136285277 4287455952 18446744073709551615 134723339 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29303/statm: 2752 2544 234 433 0 2317 0 Current children cumulated CPU time (s) 290.09 Current children cumulated vsize (KiB) 13604 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.51 s] /proc/loadavg: 1.00 1.03 1.01 2/36 29316 /proc/meminfo: memFree=657132/1048576 swapFree=0/0 [pid=29294] ppid=29293 vsize=2596 CPUtime=2.23 /proc/29294/stat : 29294 (aspcud-1.5) S 29293 29294 19908 34817 19908 4202496 580 16308 0 0 0 0 219 4 16 0 1 0 65386858 2658304 298 1283457024 134512640 135304128 4294023488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29294/statm: 649 298 251 194 0 36 0 [pid=29303] ppid=29294 vsize=11008 CPUtime=287.86 /proc/29303/stat : 29303 (clasp) R 29294 29294 19908 34817 19908 4202496 2882 0 0 0 28786 0 0 0 25 0 1 0 65386859 11272192 2544 1283457024 134512640 136285277 4287455952 18446744073709551615 134723339 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29303/statm: 2752 2544 234 433 0 2317 0 Current children cumulated CPU time (s) 290.09 Current children cumulated vsize (KiB) 13604 Child status: 0 Real time (s): 290.531 CPU time (s): 290.138 CPU user time (s): 290.066 CPU system time (s): 0.072004 CPU usage (%): 99.8649 Max. virtual memory (cumulated for all children) (KiB): 56044 getrusage(RUSAGE_CHILDREN,...) data: user time used= 290.066 system time used= 0.072004 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 23341 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= 213 involuntary context switches= 3765 runsolver used 0 second user time and 0 second system time The end