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/rand90.cudf.s-e-l-s-s.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/incremental/s-e-l-s-s//rand90.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand90.cudf.s-e-l-s-s.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.14 1.11 1.03 5/36 13237 /proc/meminfo: memFree=429516/1048576 swapFree=0/0 [pid=13235] ppid=13234 vsize=2588 CPUtime=0 /proc/13235/stat : 13235 (aspcud-trendy-1) S 13234 13235 1511 34817 1511 4202496 374 0 0 0 0 0 0 0 18 0 1 0 2987094 2650112 280 1283457024 134512640 135304128 4290696720 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/13235/statm: 647 280 234 194 0 34 0 [pid=13236] ppid=13235 vsize=2588 CPUtime=0 /proc/13236/stat : 13236 (aspcud-trendy-1) R 13235 13235 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 2987094 2650112 133 1283457024 134512640 135304128 4290696720 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/13236/statm: 647 133 86 194 0 34 0 [pid=13237] ppid=13236 vsize=2588 CPUtime=0 /proc/13237/stat : 13237 (aspcud-trendy-1) R 13236 13235 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 2987094 2650112 47 1283457024 134512640 135304128 4290696720 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/13237/statm: 647 47 0 194 0 34 0 [startup+0.205211 s] /proc/loadavg: 1.14 1.11 1.03 5/36 13237 /proc/meminfo: memFree=429516/1048576 swapFree=0/0 [pid=13235] ppid=13234 vsize=2596 CPUtime=0.01 /proc/13235/stat : 13235 (aspcud-trendy-1) S 13234 13235 1511 34817 1511 4202496 625 2226 0 0 0 0 0 1 25 0 1 0 2987094 2658304 299 1283457024 134512640 135304128 4290696720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13235/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.305224 s] /proc/loadavg: 1.14 1.11 1.03 5/36 13237 /proc/meminfo: memFree=429516/1048576 swapFree=0/0 [pid=13235] ppid=13234 vsize=2596 CPUtime=0.01 /proc/13235/stat : 13235 (aspcud-trendy-1) S 13234 13235 1511 34817 1511 4202496 625 2226 0 0 0 0 0 1 25 0 1 0 2987094 2658304 299 1283457024 134512640 135304128 4290696720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13235/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.405242 s] /proc/loadavg: 1.14 1.11 1.03 5/36 13237 /proc/meminfo: memFree=429516/1048576 swapFree=0/0 [pid=13235] ppid=13234 vsize=2596 CPUtime=0.01 /proc/13235/stat : 13235 (aspcud-trendy-1) S 13234 13235 1511 34817 1511 4202496 625 2226 0 0 0 0 0 1 25 0 1 0 2987094 2658304 299 1283457024 134512640 135304128 4290696720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13235/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.705291 s] /proc/loadavg: 1.14 1.11 1.03 5/36 13237 /proc/meminfo: memFree=429516/1048576 swapFree=0/0 [pid=13235] ppid=13234 vsize=2596 CPUtime=0.01 /proc/13235/stat : 13235 (aspcud-trendy-1) S 13234 13235 1511 34817 1511 4202496 625 2226 0 0 0 0 0 1 25 0 1 0 2987094 2658304 299 1283457024 134512640 135304128 4290696720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13235/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+1.50541 s] /proc/loadavg: 1.13 1.10 1.03 2/38 13249 /proc/meminfo: memFree=402572/1048576 swapFree=0/0 [pid=13235] ppid=13234 vsize=2596 CPUtime=0.01 /proc/13235/stat : 13235 (aspcud-trendy-1) S 13234 13235 1511 34817 1511 4202496 625 2226 0 0 0 0 0 1 25 0 1 0 2987094 2658304 299 1283457024 134512640 135304128 4290696720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13235/statm: 649 299 251 194 0 36 0 [pid=13247] ppid=13235 vsize=1924 CPUtime=0 /proc/13247/stat : 13247 (clasp) S 13235 13235 1511 34817 1511 4202496 292 0 0 0 0 0 0 0 25 0 1 0 2987095 1970176 159 1283457024 134512640 136285277 4292825056 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/13247/statm: 481 159 144 433 0 46 0 [pid=13248] ppid=13235 vsize=2584 CPUtime=0 /proc/13248/stat : 13248 (gringo) S 13235 13235 1511 34817 1511 4202496 405 0 0 0 0 0 0 0 25 0 1 0 2987095 2646016 272 1283457024 134512640 136933539 4291716928 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/13248/statm: 646 272 242 592 0 51 0 [pid=13249] ppid=13235 vsize=40660 CPUtime=1.49 /proc/13249/stat : 13249 (cudf2lp) R 13235 13235 1511 34817 1511 4202496 11711 0 0 0 145 4 0 0 25 0 1 0 2987096 41635840 8800 1283457024 134512640 135786343 4294926960 18446744073709551615 134566250 0 0 6 0 0 0 0 17 0 0 0 0 /proc/13249/statm: 10165 8800 126 311 0 9852 0 Current children cumulated CPU time (s) 1.5 Current children cumulated vsize (KiB) 47764 [startup+3.10574 s] /proc/loadavg: 1.13 1.10 1.03 3/38 13249 /proc/meminfo: memFree=371324/1048576 swapFree=0/0 [pid=13235] ppid=13234 vsize=2596 CPUtime=0.01 /proc/13235/stat : 13235 (aspcud-trendy-1) S 13234 13235 1511 34817 1511 4202496 625 2226 0 0 0 0 0 1 25 0 1 0 2987094 2658304 299 1283457024 134512640 135304128 4290696720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13235/statm: 649 299 251 194 0 36 0 [pid=13247] ppid=13235 vsize=17312 CPUtime=0.05 /proc/13247/stat : 13247 (clasp) S 13235 13235 1511 34817 1511 4202496 4789 0 0 0 3 2 0 0 18 0 1 0 2987095 17727488 3998 1283457024 134512640 136285277 4292825056 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/13247/statm: 4328 3998 177 433 0 3893 0 [pid=13248] ppid=13235 vsize=22076 CPUtime=0.79 /proc/13248/stat : 13248 (gringo) S 13235 13235 1511 34817 1511 4202496 6881 0 0 0 74 5 0 0 18 0 1 0 2987095 22605824 4608 1283457024 134512640 136933539 4291716928 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/13248/statm: 5519 4608 242 592 0 4924 0 [pid=13249] ppid=13235 vsize=46940 CPUtime=2.24 /proc/13249/stat : 13249 (cudf2lp) R 13235 13235 1511 34817 1511 4202496 16201 0 0 0 217 7 0 0 25 0 1 0 2987096 48066560 5319 1283457024 134512640 135786343 4294926960 18446744073709551615 135407694 0 0 6 0 0 0 0 17 0 0 0 0 /proc/13249/statm: 11735 5319 138 311 0 11422 0 Current children cumulated CPU time (s) 3.09 Current children cumulated vsize (KiB) 88924 [startup+6.30837 s] /proc/loadavg: 1.13 1.10 1.03 2/36 13249 /proc/meminfo: memFree=374464/1048576 swapFree=0/0 [pid=13235] ppid=13234 vsize=2596 CPUtime=4.27 /proc/13235/stat : 13235 (aspcud-trendy-1) S 13234 13235 1511 34817 1511 4202496 626 38013 0 0 0 0 411 16 18 0 1 0 2987094 2658304 299 1283457024 134512640 135304128 4290696720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13235/statm: 649 299 251 194 0 36 0 [pid=13247] ppid=13235 vsize=55456 CPUtime=2.04 /proc/13247/stat : 13247 (clasp) R 13235 13235 1511 34817 1511 4202496 17222 0 0 0 198 6 0 0 20 0 1 0 2987095 56786944 13617 1283457024 134512640 136285277 4292825056 18446744073709551615 134669525 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/13247/statm: 13864 13617 234 433 0 13429 0 Current children cumulated CPU time (s) 6.31 Current children cumulated vsize (KiB) 58052 [startup+12.7098 s] /proc/loadavg: 1.11 1.10 1.03 2/36 13249 /proc/meminfo: memFree=375340/1048576 swapFree=0/0 [pid=13235] ppid=13234 vsize=2596 CPUtime=4.27 /proc/13235/stat : 13235 (aspcud-trendy-1) S 13234 13235 1511 34817 1511 4202496 626 38013 0 0 0 0 411 16 18 0 1 0 2987094 2658304 299 1283457024 134512640 135304128 4290696720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13235/statm: 649 299 251 194 0 36 0 [pid=13247] ppid=13235 vsize=55456 CPUtime=8.44 /proc/13247/stat : 13247 (clasp) R 13235 13235 1511 34817 1511 4202496 17243 0 0 0 837 7 0 0 25 0 1 0 2987095 56786944 13638 1283457024 134512640 136285277 4292825056 18446744073709551615 134963464 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/13247/statm: 13864 13638 234 433 0 13429 0 Current children cumulated CPU time (s) 12.71 Current children cumulated vsize (KiB) 58052 [startup+25.5021 s] /proc/loadavg: 1.09 1.10 1.03 2/36 13249 /proc/meminfo: memFree=365172/1048576 swapFree=0/0 [pid=13235] ppid=13234 vsize=2596 CPUtime=4.27 /proc/13235/stat : 13235 (aspcud-trendy-1) S 13234 13235 1511 34817 1511 4202496 626 38013 0 0 0 0 411 16 18 0 1 0 2987094 2658304 299 1283457024 134512640 135304128 4290696720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13235/statm: 649 299 251 194 0 36 0 [pid=13247] ppid=13235 vsize=66248 CPUtime=21.23 /proc/13247/stat : 13247 (clasp) R 13235 13235 1511 34817 1511 4202496 19921 0 0 0 2112 11 0 0 25 0 1 0 2987095 67837952 16316 1283457024 134512640 136285277 4292825056 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/13247/statm: 16562 16316 234 433 0 16127 0 Current children cumulated CPU time (s) 25.5 Current children cumulated vsize (KiB) 68844 [startup+51.1076 s] /proc/loadavg: 1.06 1.09 1.03 2/35 13249 /proc/meminfo: memFree=333188/1048576 swapFree=0/0 [pid=13235] ppid=13234 vsize=2596 CPUtime=4.27 /proc/13235/stat : 13235 (aspcud-trendy-1) S 13234 13235 1511 34817 1511 4202496 626 38013 0 0 0 0 411 16 18 0 1 0 2987094 2658304 299 1283457024 134512640 135304128 4290696720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13235/statm: 649 299 251 194 0 36 0 [pid=13247] ppid=13235 vsize=99992 CPUtime=46.81 /proc/13247/stat : 13247 (clasp) R 13235 13235 1511 34817 1511 4202496 28352 0 0 0 4669 12 0 0 25 0 1 0 2987095 102391808 24747 1283457024 134512640 136285277 4292825056 18446744073709551615 134945933 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/13247/statm: 24998 24747 234 433 0 24563 0 Current children cumulated CPU time (s) 51.08 Current children cumulated vsize (KiB) 102588 [startup+102.31 s] /proc/loadavg: 1.02 1.07 1.02 2/35 13249 /proc/meminfo: memFree=296360/1048576 swapFree=0/0 [pid=13235] ppid=13234 vsize=2596 CPUtime=4.27 /proc/13235/stat : 13235 (aspcud-trendy-1) S 13234 13235 1511 34817 1511 4202496 626 38013 0 0 0 0 411 16 18 0 1 0 2987094 2658304 299 1283457024 134512640 135304128 4290696720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13235/statm: 649 299 251 194 0 36 0 [pid=13247] ppid=13235 vsize=134984 CPUtime=97.97 /proc/13247/stat : 13247 (clasp) R 13235 13235 1511 34817 1511 4202496 37080 0 0 0 9778 19 0 0 25 0 1 0 2987095 138223616 33475 1283457024 134512640 136285277 4292825056 18446744073709551615 134723291 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/13247/statm: 33746 33475 234 433 0 33311 0 Current children cumulated CPU time (s) 102.24 Current children cumulated vsize (KiB) 137580 [startup+162.307 s] /proc/loadavg: 1.01 1.06 1.01 2/35 13249 /proc/meminfo: memFree=273792/1048576 swapFree=0/0 [pid=13235] ppid=13234 vsize=2596 CPUtime=4.27 /proc/13235/stat : 13235 (aspcud-trendy-1) S 13234 13235 1511 34817 1511 4202496 626 38013 0 0 0 0 411 16 18 0 1 0 2987094 2658304 299 1283457024 134512640 135304128 4290696720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13235/statm: 649 299 251 194 0 36 0 [pid=13247] ppid=13235 vsize=157424 CPUtime=157.9 /proc/13247/stat : 13247 (clasp) R 13235 13235 1511 34817 1511 4202496 42703 0 0 0 15769 21 0 0 25 0 1 0 2987095 161202176 39098 1283457024 134512640 136285277 4292825056 18446744073709551615 134723339 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/13247/statm: 39356 39098 234 433 0 38921 0 Current children cumulated CPU time (s) 162.17 Current children cumulated vsize (KiB) 160020 [startup+222.313 s] /proc/loadavg: 1.00 1.04 1.01 2/35 13249 /proc/meminfo: memFree=260152/1048576 swapFree=0/0 [pid=13235] ppid=13234 vsize=2596 CPUtime=4.27 /proc/13235/stat : 13235 (aspcud-trendy-1) S 13234 13235 1511 34817 1511 4202496 626 38013 0 0 0 0 411 16 18 0 1 0 2987094 2658304 299 1283457024 134512640 135304128 4290696720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13235/statm: 649 299 251 194 0 36 0 [pid=13247] ppid=13235 vsize=171200 CPUtime=217.89 /proc/13247/stat : 13247 (clasp) R 13235 13235 1511 34817 1511 4202496 46117 0 0 0 21766 23 0 0 25 0 1 0 2987095 175308800 42512 1283457024 134512640 136285277 4292825056 18446744073709551615 134733768 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/13247/statm: 42800 42512 234 433 0 42365 0 Current children cumulated CPU time (s) 222.16 Current children cumulated vsize (KiB) 173796 [startup+282.309 s] /proc/loadavg: 1.00 1.03 1.00 2/37 13252 /proc/meminfo: memFree=192796/1048576 swapFree=0/0 [pid=13235] ppid=13234 vsize=2596 CPUtime=4.27 /proc/13235/stat : 13235 (aspcud-trendy-1) S 13234 13235 1511 34817 1511 4202496 626 38013 0 0 0 0 411 16 18 0 1 0 2987094 2658304 299 1283457024 134512640 135304128 4290696720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13235/statm: 649 299 251 194 0 36 0 [pid=13247] ppid=13235 vsize=238208 CPUtime=277.84 /proc/13247/stat : 13247 (clasp) R 13235 13235 1511 34817 1511 4202496 62885 0 0 0 27749 35 0 0 25 0 1 0 2987095 243924992 59280 1283457024 134512640 136285277 4292825056 18446744073709551615 134967003 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/13247/statm: 59552 59280 234 433 0 59117 0 Current children cumulated CPU time (s) 282.11 Current children cumulated vsize (KiB) 240804 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.211 s] /proc/loadavg: 1.00 1.03 1.00 2/37 13252 /proc/meminfo: memFree=195028/1048576 swapFree=0/0 [pid=13235] ppid=13234 vsize=2596 CPUtime=4.27 /proc/13235/stat : 13235 (aspcud-trendy-1) S 13234 13235 1511 34817 1511 4202496 626 38013 0 0 0 0 411 16 18 0 1 0 2987094 2658304 299 1283457024 134512640 135304128 4290696720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13235/statm: 649 299 251 194 0 36 0 [pid=13247] ppid=13235 vsize=235288 CPUtime=285.74 /proc/13247/stat : 13247 (clasp) R 13235 13235 1511 34817 1511 4202496 62886 0 0 0 28539 35 0 0 25 0 1 0 2987095 240934912 58552 1283457024 134512640 136285277 4292825056 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/13247/statm: 58822 58552 234 433 0 58387 0 Current children cumulated CPU time (s) 290.01 Current children cumulated vsize (KiB) 237884 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.211 s] /proc/loadavg: 1.00 1.03 1.00 2/37 13252 /proc/meminfo: memFree=195028/1048576 swapFree=0/0 [pid=13235] ppid=13234 vsize=2596 CPUtime=4.27 /proc/13235/stat : 13235 (aspcud-trendy-1) S 13234 13235 1511 34817 1511 4202496 626 38013 0 0 0 0 411 16 18 0 1 0 2987094 2658304 299 1283457024 134512640 135304128 4290696720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13235/statm: 649 299 251 194 0 36 0 [pid=13247] ppid=13235 vsize=235288 CPUtime=285.74 /proc/13247/stat : 13247 (clasp) R 13235 13235 1511 34817 1511 4202496 62886 0 0 0 28539 35 0 0 25 0 1 0 2987095 240934912 58552 1283457024 134512640 136285277 4292825056 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/13247/statm: 58822 58552 234 433 0 58387 0 Current children cumulated CPU time (s) 290.01 Current children cumulated vsize (KiB) 237884 Child status: 0 Real time (s): 290.249 CPU time (s): 290.058 CPU user time (s): 289.518 CPU system time (s): 0.540033 CPU usage (%): 99.9344 Max. virtual memory (cumulated for all children) (KiB): 240804 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.518 system time used= 0.540033 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 105231 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= 2919 involuntary context switches= 5768 runsolver used 0 second user time and 0 second system time The end