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/201108241238/aspcud-trendy-1.5/rand408.cudf.s-e-l.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/incremental/s-e-l/rand408.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand408.cudf.s-e-l.result 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.00 1.01 1.00 5/37 11873 /proc/meminfo: memFree=526528/1048576 swapFree=0/0 [pid=11871] ppid=11870 vsize=2584 CPUtime=0 /proc/11871/stat : 11871 (aspcud-trendy-1) S 11870 11871 1511 34817 1511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 2779553 2646016 279 1283457024 134512640 135304128 4292810784 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/11871/statm: 646 279 234 194 0 33 0 [pid=11872] ppid=11871 vsize=2584 CPUtime=0 /proc/11872/stat : 11872 (aspcud-trendy-1) R 11871 11871 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 2779553 2646016 132 1283457024 134512640 135304128 4292810784 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/11872/statm: 646 132 86 194 0 33 0 [pid=11873] ppid=11872 vsize=2584 CPUtime=0 /proc/11873/stat : 11873 (aspcud-trendy-1) R 11872 11871 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 2779553 2646016 46 1283457024 134512640 135304128 4292810784 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/11873/statm: 646 46 0 194 0 33 0 [startup+0.205682 s] /proc/loadavg: 1.00 1.01 1.00 5/37 11873 /proc/meminfo: memFree=526528/1048576 swapFree=0/0 [pid=11871] ppid=11870 vsize=2592 CPUtime=0 /proc/11871/stat : 11871 (aspcud-trendy-1) S 11870 11871 1511 34817 1511 4202496 623 2231 0 0 0 0 0 0 25 0 1 0 2779553 2654208 298 1283457024 134512640 135304128 4292810784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11871/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.305696 s] /proc/loadavg: 1.00 1.01 1.00 5/37 11873 /proc/meminfo: memFree=526528/1048576 swapFree=0/0 [pid=11871] ppid=11870 vsize=2592 CPUtime=0 /proc/11871/stat : 11871 (aspcud-trendy-1) S 11870 11871 1511 34817 1511 4202496 623 2231 0 0 0 0 0 0 25 0 1 0 2779553 2654208 298 1283457024 134512640 135304128 4292810784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11871/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.405718 s] /proc/loadavg: 1.00 1.01 1.00 5/37 11873 /proc/meminfo: memFree=526528/1048576 swapFree=0/0 [pid=11871] ppid=11870 vsize=2592 CPUtime=0 /proc/11871/stat : 11871 (aspcud-trendy-1) S 11870 11871 1511 34817 1511 4202496 623 2231 0 0 0 0 0 0 25 0 1 0 2779553 2654208 298 1283457024 134512640 135304128 4292810784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11871/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.705796 s] /proc/loadavg: 1.00 1.01 1.00 5/37 11873 /proc/meminfo: memFree=526528/1048576 swapFree=0/0 [pid=11871] ppid=11870 vsize=2592 CPUtime=0 /proc/11871/stat : 11871 (aspcud-trendy-1) S 11870 11871 1511 34817 1511 4202496 623 2231 0 0 0 0 0 0 25 0 1 0 2779553 2654208 298 1283457024 134512640 135304128 4292810784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11871/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+1.50595 s] /proc/loadavg: 1.00 1.01 1.00 2/39 11885 /proc/meminfo: memFree=496484/1048576 swapFree=0/0 [pid=11871] ppid=11870 vsize=2592 CPUtime=0 /proc/11871/stat : 11871 (aspcud-trendy-1) S 11870 11871 1511 34817 1511 4202496 623 2231 0 0 0 0 0 0 25 0 1 0 2779553 2654208 298 1283457024 134512640 135304128 4292810784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11871/statm: 648 298 251 194 0 35 0 [pid=11883] ppid=11871 vsize=6372 CPUtime=0 /proc/11883/stat : 11883 (clasp) S 11871 11871 1511 34817 1511 4202496 1509 0 0 0 0 0 0 0 18 0 1 0 2779554 6524928 1294 1283457024 134512640 136285277 4289426592 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/11883/statm: 1593 1294 177 433 0 1158 0 [pid=11884] ppid=11871 vsize=9020 CPUtime=0.21 /proc/11884/stat : 11884 (gringo) S 11871 11871 1511 34817 1511 4202496 2403 0 0 0 20 1 0 0 18 0 1 0 2779554 9236480 1591 1283457024 134512640 136933539 4288154592 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/11884/statm: 2255 1591 242 592 0 1660 0 [pid=11885] ppid=11871 vsize=30572 CPUtime=1.27 /proc/11885/stat : 11885 (cudf2lp) R 11871 11871 1511 34817 1511 4202496 10056 0 0 0 124 3 0 0 25 0 1 0 2779554 31305728 7426 1283457024 134512640 135786343 4290877072 18446744073709551615 134545744 0 0 6 0 0 0 0 17 0 0 0 0 /proc/11885/statm: 7643 7426 137 311 0 7330 0 Current children cumulated CPU time (s) 1.48 Current children cumulated vsize (KiB) 48556 [startup+3.10634 s] /proc/loadavg: 1.08 1.03 1.01 3/38 11885 /proc/meminfo: memFree=482612/1048576 swapFree=0/0 [pid=11871] ppid=11870 vsize=2592 CPUtime=2.56 /proc/11871/stat : 11871 (aspcud-trendy-1) S 11870 11871 1511 34817 1511 4202496 624 25377 0 0 0 0 249 7 18 0 1 0 2779553 2654208 298 1283457024 134512640 135304128 4292810784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11871/statm: 648 298 251 194 0 35 0 [pid=11883] ppid=11871 vsize=35664 CPUtime=0.54 /proc/11883/stat : 11883 (clasp) R 11871 11871 1511 34817 1511 4202496 10373 0 0 0 52 2 0 0 18 0 1 0 2779554 36519936 8626 1283457024 134512640 136285277 4289426592 18446744073709551615 134895984 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/11883/statm: 8916 8626 218 433 0 8481 0 Current children cumulated CPU time (s) 3.1 Current children cumulated vsize (KiB) 38256 [startup+6.30707 s] /proc/loadavg: 1.08 1.03 1.01 2/37 11885 /proc/meminfo: memFree=492672/1048576 swapFree=0/0 [pid=11871] ppid=11870 vsize=2592 CPUtime=2.56 /proc/11871/stat : 11871 (aspcud-trendy-1) S 11870 11871 1511 34817 1511 4202496 624 25377 0 0 0 0 249 7 18 0 1 0 2779553 2654208 298 1283457024 134512640 135304128 4292810784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11871/statm: 648 298 251 194 0 35 0 [pid=11883] ppid=11871 vsize=35120 CPUtime=3.74 /proc/11883/stat : 11883 (clasp) R 11871 11871 1511 34817 1511 4202496 10403 0 0 0 372 2 0 0 25 0 1 0 2779554 35962880 8545 1283457024 134512640 136285277 4289426592 18446744073709551615 134931519 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/11883/statm: 8780 8545 234 433 0 8345 0 Current children cumulated CPU time (s) 6.3 Current children cumulated vsize (KiB) 37712 [startup+12.7089 s] /proc/loadavg: 1.07 1.03 1.00 2/37 11886 /proc/meminfo: memFree=492812/1048576 swapFree=0/0 [pid=11871] ppid=11870 vsize=2592 CPUtime=2.56 /proc/11871/stat : 11871 (aspcud-trendy-1) S 11870 11871 1511 34817 1511 4202496 624 25377 0 0 0 0 249 7 18 0 1 0 2779553 2654208 298 1283457024 134512640 135304128 4292810784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11871/statm: 648 298 251 194 0 35 0 [pid=11883] ppid=11871 vsize=35120 CPUtime=10.14 /proc/11883/stat : 11883 (clasp) R 11871 11871 1511 34817 1511 4202496 10403 0 0 0 1012 2 0 0 25 0 1 0 2779554 35962880 8545 1283457024 134512640 136285277 4289426592 18446744073709551615 134733725 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/11883/statm: 8780 8545 234 433 0 8345 0 Current children cumulated CPU time (s) 12.7 Current children cumulated vsize (KiB) 37712 [startup+25.5117 s] /proc/loadavg: 1.06 1.03 1.00 2/37 11887 /proc/meminfo: memFree=480412/1048576 swapFree=0/0 [pid=11871] ppid=11870 vsize=2592 CPUtime=2.56 /proc/11871/stat : 11871 (aspcud-trendy-1) S 11870 11871 1511 34817 1511 4202496 624 25377 0 0 0 0 249 7 18 0 1 0 2779553 2654208 298 1283457024 134512640 135304128 4292810784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11871/statm: 648 298 251 194 0 35 0 [pid=11883] ppid=11871 vsize=48052 CPUtime=22.93 /proc/11883/stat : 11883 (clasp) R 11871 11871 1511 34817 1511 4202496 13620 0 0 0 2291 2 0 0 25 0 1 0 2779554 49205248 11762 1283457024 134512640 136285277 4289426592 18446744073709551615 134733781 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/11883/statm: 12013 11762 234 433 0 11578 0 Current children cumulated CPU time (s) 25.49 Current children cumulated vsize (KiB) 50644 [startup+51.1075 s] /proc/loadavg: 1.04 1.02 1.00 2/36 11888 /proc/meminfo: memFree=467656/1048576 swapFree=0/0 [pid=11871] ppid=11870 vsize=2592 CPUtime=2.56 /proc/11871/stat : 11871 (aspcud-trendy-1) S 11870 11871 1511 34817 1511 4202496 624 25377 0 0 0 0 249 7 18 0 1 0 2779553 2654208 298 1283457024 134512640 135304128 4292810784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11871/statm: 648 298 251 194 0 35 0 [pid=11883] ppid=11871 vsize=60900 CPUtime=48.51 /proc/11883/stat : 11883 (clasp) R 11871 11871 1511 34817 1511 4202496 16831 0 0 0 4848 3 0 0 25 0 1 0 2779554 62361600 14973 1283457024 134512640 136285277 4289426592 18446744073709551615 134959552 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/11883/statm: 15225 14973 234 433 0 14790 0 Current children cumulated CPU time (s) 51.07 Current children cumulated vsize (KiB) 63492 [startup+102.311 s] /proc/loadavg: 1.05 1.03 1.00 2/35 11888 /proc/meminfo: memFree=437408/1048576 swapFree=0/0 [pid=11871] ppid=11870 vsize=2592 CPUtime=2.56 /proc/11871/stat : 11871 (aspcud-trendy-1) S 11870 11871 1511 34817 1511 4202496 624 25377 0 0 0 0 249 7 18 0 1 0 2779553 2654208 298 1283457024 134512640 135304128 4292810784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11871/statm: 648 298 251 194 0 35 0 [pid=11883] ppid=11871 vsize=93904 CPUtime=99.65 /proc/11883/stat : 11883 (clasp) R 11871 11871 1511 34817 1511 4202496 25065 0 0 0 9959 6 0 0 25 0 1 0 2779554 96157696 23207 1283457024 134512640 136285277 4289426592 18446744073709551615 134960063 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/11883/statm: 23476 23207 234 433 0 23041 0 Current children cumulated CPU time (s) 102.21 Current children cumulated vsize (KiB) 96496 [startup+162.305 s] /proc/loadavg: 1.02 1.02 1.00 2/35 11888 /proc/meminfo: memFree=395372/1048576 swapFree=0/0 [pid=11871] ppid=11870 vsize=2592 CPUtime=2.56 /proc/11871/stat : 11871 (aspcud-trendy-1) S 11870 11871 1511 34817 1511 4202496 624 25377 0 0 0 0 249 7 18 0 1 0 2779553 2654208 298 1283457024 134512640 135304128 4292810784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11871/statm: 648 298 251 194 0 35 0 [pid=11883] ppid=11871 vsize=133400 CPUtime=159.59 /proc/11883/stat : 11883 (clasp) R 11871 11871 1511 34817 1511 4202496 34863 0 0 0 15940 19 0 0 25 0 1 0 2779554 136601600 33005 1283457024 134512640 136285277 4289426592 18446744073709551615 134615170 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/11883/statm: 33350 33005 234 433 0 32915 0 Current children cumulated CPU time (s) 162.15 Current children cumulated vsize (KiB) 135992 [startup+222.31 s] /proc/loadavg: 1.00 1.02 1.00 2/35 11888 /proc/meminfo: memFree=369084/1048576 swapFree=0/0 [pid=11871] ppid=11870 vsize=2592 CPUtime=2.56 /proc/11871/stat : 11871 (aspcud-trendy-1) S 11870 11871 1511 34817 1511 4202496 624 25377 0 0 0 0 249 7 18 0 1 0 2779553 2654208 298 1283457024 134512640 135304128 4292810784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11871/statm: 648 298 251 194 0 35 0 [pid=11883] ppid=11871 vsize=159480 CPUtime=219.55 /proc/11883/stat : 11883 (clasp) R 11871 11871 1511 34817 1511 4202496 41523 0 0 0 21931 24 0 0 25 0 1 0 2779554 163307520 39560 1283457024 134512640 136285277 4289426592 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/11883/statm: 39870 39560 234 433 0 39435 0 Current children cumulated CPU time (s) 222.11 Current children cumulated vsize (KiB) 162072 [startup+282.309 s] /proc/loadavg: 1.00 1.01 1.00 2/35 11888 /proc/meminfo: memFree=368712/1048576 swapFree=0/0 [pid=11871] ppid=11870 vsize=2592 CPUtime=2.56 /proc/11871/stat : 11871 (aspcud-trendy-1) S 11870 11871 1511 34817 1511 4202496 624 25377 0 0 0 0 249 7 18 0 1 0 2779553 2654208 298 1283457024 134512640 135304128 4292810784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11871/statm: 648 298 251 194 0 35 0 [pid=11883] ppid=11871 vsize=159744 CPUtime=279.48 /proc/11883/stat : 11883 (clasp) R 11871 11871 1511 34817 1511 4202496 41601 0 0 0 27923 25 0 0 25 0 1 0 2779554 163577856 39638 1283457024 134512640 136285277 4289426592 18446744073709551615 134959776 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/11883/statm: 39936 39638 234 433 0 39501 0 Current children cumulated CPU time (s) 282.04 Current children cumulated vsize (KiB) 162336 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.31 s] /proc/loadavg: 1.00 1.01 1.00 2/35 11888 /proc/meminfo: memFree=368092/1048576 swapFree=0/0 [pid=11871] ppid=11870 vsize=2592 CPUtime=2.56 /proc/11871/stat : 11871 (aspcud-trendy-1) S 11870 11871 1511 34817 1511 4202496 624 25377 0 0 0 0 249 7 18 0 1 0 2779553 2654208 298 1283457024 134512640 135304128 4292810784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11871/statm: 648 298 251 194 0 35 0 [pid=11883] ppid=11871 vsize=160404 CPUtime=287.47 /proc/11883/stat : 11883 (clasp) R 11871 11871 1511 34817 1511 4202496 41753 0 0 0 28722 25 0 0 25 0 1 0 2779554 164253696 39790 1283457024 134512640 136285277 4289426592 18446744073709551615 134930669 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/11883/statm: 40101 39790 234 433 0 39666 0 Current children cumulated CPU time (s) 290.03 Current children cumulated vsize (KiB) 162996 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.31 s] /proc/loadavg: 1.00 1.01 1.00 2/35 11888 /proc/meminfo: memFree=368092/1048576 swapFree=0/0 [pid=11871] ppid=11870 vsize=2592 CPUtime=2.56 /proc/11871/stat : 11871 (aspcud-trendy-1) S 11870 11871 1511 34817 1511 4202496 624 25377 0 0 0 0 249 7 18 0 1 0 2779553 2654208 298 1283457024 134512640 135304128 4292810784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11871/statm: 648 298 251 194 0 35 0 [pid=11883] ppid=11871 vsize=160404 CPUtime=287.47 /proc/11883/stat : 11883 (clasp) R 11871 11871 1511 34817 1511 4202496 41753 0 0 0 28722 25 0 0 25 0 1 0 2779554 164253696 39790 1283457024 134512640 136285277 4289426592 18446744073709551615 134930669 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/11883/statm: 40101 39790 234 433 0 39666 0 Current children cumulated CPU time (s) 290.03 Current children cumulated vsize (KiB) 162996 Child status: 0 Real time (s): 290.343 CPU time (s): 290.074 CPU user time (s): 289.714 CPU system time (s): 0.360022 CPU usage (%): 99.9073 Max. virtual memory (cumulated for all children) (KiB): 162996 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.714 system time used= 0.360022 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 71422 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= 1249 involuntary context switches= 4279 runsolver used 0 second user time and 0 second system time The end