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/201108251442/aspcud-paranoid-1.5/rand58.cudf.s-e-l.log.runsolver ./aspcud-paranoid-1.5 /home/misc2010/data/2011/incremental/s-e-l/rand58.cudf /home/misc2010/tmp/201108251442/aspcud-paranoid-1.5/rand58.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.00 1.00 6/36 15655 /proc/meminfo: memFree=389480/1048576 swapFree=0/0 [pid=15639] ppid=15638 vsize=2596 CPUtime=0 /proc/15639/stat : 15639 (aspcud-paranoid) R 15638 15639 4778 34817 4778 4202496 630 2933 0 0 0 0 0 0 25 0 1 0 10913628 2658304 298 1283457024 134512640 135304128 4290254240 18446744073709551615 4294960130 0 65538 4 1132560123 0 0 0 17 0 0 0 0 /proc/15639/statm: 649 298 250 194 0 36 0 [pid=15653] ppid=15639 vsize=2596 CPUtime=0 /proc/15653/stat : 15653 (aspcud-paranoid) R 15639 15639 4778 34817 4778 4202560 111 0 0 0 0 0 0 0 25 0 1 0 10913630 2658304 132 1283457024 134512640 135304128 4290254240 18446744073709551615 4294960130 0 0 6 1132494585 0 0 0 17 0 0 0 0 /proc/15653/statm: 649 132 83 194 0 36 0 [pid=15654] ppid=15639 vsize=2596 CPUtime=0.01 /proc/15654/stat : 15654 (aspcud-paranoid) S 15639 15639 4778 34817 4778 4202560 111 0 0 0 0 1 0 0 25 0 1 0 10913630 2658304 132 1283457024 134512640 135304128 4290254240 18446744073709551615 4294960130 0 0 6 1132494585 18446744071564457842 0 0 17 0 0 0 0 /proc/15654/statm: 649 132 83 194 0 36 0 [pid=15655] ppid=15639 vsize=2596 CPUtime=0 /proc/15655/stat : 15655 (aspcud-paranoid) R 15639 15639 4778 34817 4778 4202560 0 0 0 0 0 0 0 0 25 0 1 0 10913630 2658304 48 1283457024 134512640 135304128 4290254240 18446744073709551615 4294960130 0 65538 4 1132560123 0 0 0 17 0 0 0 0 /proc/15655/statm: 649 48 0 194 0 36 0 [startup+0.196988 s] /proc/loadavg: 1.00 1.00 1.00 6/36 15655 /proc/meminfo: memFree=389480/1048576 swapFree=0/0 [pid=15639] ppid=15638 vsize=2596 CPUtime=0 /proc/15639/stat : 15639 (aspcud-paranoid) S 15638 15639 4778 34817 4778 4202496 656 2933 0 0 0 0 0 0 25 0 1 0 10913628 2658304 299 1283457024 134512640 135304128 4290254240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15639/statm: 649 299 251 194 0 36 0 [pid=15653] ppid=15639 vsize=1928 CPUtime=0 /proc/15653/stat : 15653 (clasp) S 15639 15639 4778 34817 4778 4202496 292 0 0 0 0 0 0 0 25 0 1 0 10913630 1974272 159 1283457024 134512640 136285277 4294834624 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/15653/statm: 482 159 144 433 0 47 0 [pid=15654] ppid=15639 vsize=2580 CPUtime=0.01 /proc/15654/stat : 15654 (gringo) S 15639 15639 4778 34817 4778 4202496 404 0 0 0 0 1 0 0 25 0 1 0 10913630 2641920 271 1283457024 134512640 136933539 4293685536 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/15654/statm: 645 271 242 592 0 50 0 [pid=15655] ppid=15639 vsize=7152 CPUtime=0.14 /proc/15655/stat : 15655 (cudf2lp) R 15639 15639 4778 34817 4778 4202496 1835 0 0 0 14 0 0 0 25 0 1 0 10913630 7323648 1391 1283457024 134512640 135786343 4289518912 18446744073709551615 135191577 0 0 6 0 0 0 0 17 0 0 0 0 /proc/15655/statm: 1788 1391 126 311 0 1475 0 Current children cumulated CPU time (s) 0.15 Current children cumulated vsize (KiB) 14256 [startup+0.208655 s] /proc/loadavg: 1.00 1.00 1.00 6/36 15655 /proc/meminfo: memFree=389480/1048576 swapFree=0/0 [pid=15639] ppid=15638 vsize=2596 CPUtime=0 /proc/15639/stat : 15639 (aspcud-paranoid) S 15638 15639 4778 34817 4778 4202496 656 2933 0 0 0 0 0 0 25 0 1 0 10913628 2658304 299 1283457024 134512640 135304128 4290254240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15639/statm: 649 299 251 194 0 36 0 [pid=15653] ppid=15639 vsize=1928 CPUtime=0 /proc/15653/stat : 15653 (clasp) S 15639 15639 4778 34817 4778 4202496 292 0 0 0 0 0 0 0 25 0 1 0 10913630 1974272 159 1283457024 134512640 136285277 4294834624 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/15653/statm: 482 159 144 433 0 47 0 [pid=15654] ppid=15639 vsize=2580 CPUtime=0.01 /proc/15654/stat : 15654 (gringo) S 15639 15639 4778 34817 4778 4202496 404 0 0 0 0 1 0 0 25 0 1 0 10913630 2641920 271 1283457024 134512640 136933539 4293685536 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/15654/statm: 645 271 242 592 0 50 0 [pid=15655] ppid=15639 vsize=7152 CPUtime=0.15 /proc/15655/stat : 15655 (cudf2lp) D 15639 15639 4778 34817 4778 4202496 1847 0 0 0 15 0 0 0 25 0 1 0 10913630 7323648 1403 1283457024 134512640 135786343 4289518912 18446744073709551615 135258478 0 0 6 0 18446744071564332000 0 0 17 0 0 0 0 /proc/15655/statm: 1788 1403 126 311 0 1475 0 Current children cumulated CPU time (s) 0.16 Current children cumulated vsize (KiB) 14256 [startup+0.309027 s] /proc/loadavg: 1.00 1.00 1.00 6/36 15655 /proc/meminfo: memFree=389480/1048576 swapFree=0/0 [pid=15639] ppid=15638 vsize=2596 CPUtime=0 /proc/15639/stat : 15639 (aspcud-paranoid) S 15638 15639 4778 34817 4778 4202496 656 2933 0 0 0 0 0 0 25 0 1 0 10913628 2658304 299 1283457024 134512640 135304128 4290254240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15639/statm: 649 299 251 194 0 36 0 [pid=15653] ppid=15639 vsize=1928 CPUtime=0 /proc/15653/stat : 15653 (clasp) S 15639 15639 4778 34817 4778 4202496 292 0 0 0 0 0 0 0 25 0 1 0 10913630 1974272 159 1283457024 134512640 136285277 4294834624 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/15653/statm: 482 159 144 433 0 47 0 [pid=15654] ppid=15639 vsize=2580 CPUtime=0.01 /proc/15654/stat : 15654 (gringo) S 15639 15639 4778 34817 4778 4202496 404 0 0 0 0 1 0 0 25 0 1 0 10913630 2641920 271 1283457024 134512640 136933539 4293685536 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/15654/statm: 645 271 242 592 0 50 0 [pid=15655] ppid=15639 vsize=7708 CPUtime=0.24 /proc/15655/stat : 15655 (cudf2lp) R 15639 15639 4778 34817 4778 4202496 2098 0 0 0 23 1 0 0 25 0 1 0 10913630 7892992 1654 1283457024 134512640 135786343 4289518912 18446744073709551615 134536165 0 0 6 0 0 0 0 17 0 0 0 0 /proc/15655/statm: 1927 1654 126 311 0 1614 0 Current children cumulated CPU time (s) 0.25 Current children cumulated vsize (KiB) 14812 [startup+0.704984 s] /proc/loadavg: 1.00 1.00 1.00 6/36 15655 /proc/meminfo: memFree=389480/1048576 swapFree=0/0 [pid=15639] ppid=15638 vsize=2596 CPUtime=0 /proc/15639/stat : 15639 (aspcud-paranoid) S 15638 15639 4778 34817 4778 4202496 656 2933 0 0 0 0 0 0 25 0 1 0 10913628 2658304 299 1283457024 134512640 135304128 4290254240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15639/statm: 649 299 251 194 0 36 0 [pid=15653] ppid=15639 vsize=1928 CPUtime=0 /proc/15653/stat : 15653 (clasp) S 15639 15639 4778 34817 4778 4202496 292 0 0 0 0 0 0 0 25 0 1 0 10913630 1974272 159 1283457024 134512640 136285277 4294834624 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/15653/statm: 482 159 144 433 0 47 0 [pid=15654] ppid=15639 vsize=2580 CPUtime=0.01 /proc/15654/stat : 15654 (gringo) S 15639 15639 4778 34817 4778 4202496 404 0 0 0 0 1 0 0 25 0 1 0 10913630 2641920 271 1283457024 134512640 136933539 4293685536 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/15654/statm: 645 271 242 592 0 50 0 [pid=15655] ppid=15639 vsize=21564 CPUtime=0.61 /proc/15655/stat : 15655 (cudf2lp) R 15639 15639 4778 34817 4778 4202496 6006 0 0 0 58 3 0 0 25 0 1 0 10913630 22081536 4504 1283457024 134512640 135786343 4289518912 18446744073709551615 134566179 0 0 6 0 0 0 0 17 0 0 0 0 /proc/15655/statm: 5391 4504 126 311 0 5078 0 Current children cumulated CPU time (s) 0.62 Current children cumulated vsize (KiB) 28668 [startup+1.51308 s] /proc/loadavg: 1.00 1.00 1.00 2/37 15656 /proc/meminfo: memFree=349028/1048576 swapFree=0/0 [pid=15639] ppid=15638 vsize=2596 CPUtime=0 /proc/15639/stat : 15639 (aspcud-paranoid) S 15638 15639 4778 34817 4778 4202496 656 2933 0 0 0 0 0 0 25 0 1 0 10913628 2658304 299 1283457024 134512640 135304128 4290254240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15639/statm: 649 299 251 194 0 36 0 [pid=15653] ppid=15639 vsize=5844 CPUtime=0.01 /proc/15653/stat : 15653 (clasp) S 15639 15639 4778 34817 4778 4202496 1361 0 0 0 1 0 0 0 18 0 1 0 10913630 5984256 1146 1283457024 134512640 136285277 4294834624 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/15653/statm: 1461 1146 177 433 0 1026 0 [pid=15654] ppid=15639 vsize=7404 CPUtime=0.16 /proc/15654/stat : 15654 (gringo) R 15639 15639 4778 34817 4778 4202496 1929 0 0 0 14 2 0 0 18 0 1 0 10913630 7581696 1374 1283457024 134512640 136933539 4293685536 18446744073709551615 134579791 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15654/statm: 1851 1374 242 592 0 1256 0 [pid=15655] ppid=15639 vsize=30572 CPUtime=1.2 /proc/15655/stat : 15655 (cudf2lp) R 15639 15639 4778 34817 4778 4202496 10055 0 0 0 116 4 0 0 25 0 1 0 10913630 31305728 7425 1283457024 134512640 135786343 4289518912 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/15655/statm: 7643 7425 137 311 0 7330 0 Current children cumulated CPU time (s) 1.37 Current children cumulated vsize (KiB) 46416 [startup+3.11336 s] /proc/loadavg: 1.00 1.00 1.00 3/36 15656 /proc/meminfo: memFree=337760/1048576 swapFree=0/0 [pid=15639] ppid=15638 vsize=2596 CPUtime=2.05 /proc/15639/stat : 15639 (aspcud-paranoid) S 15638 15639 4778 34817 4778 4202496 656 21050 0 0 0 0 194 11 15 0 1 0 10913628 2658304 299 1283457024 134512640 135304128 4290254240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15639/statm: 649 299 251 194 0 36 0 [pid=15653] ppid=15639 vsize=24096 CPUtime=0.92 /proc/15653/stat : 15653 (clasp) R 15639 15639 4778 34817 4778 4202496 6870 0 0 0 88 4 0 0 19 0 1 0 10913630 24674304 5778 1283457024 134512640 136285277 4294834624 18446744073709551615 134966723 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15653/statm: 6024 5778 234 433 0 5589 0 Current children cumulated CPU time (s) 2.97 Current children cumulated vsize (KiB) 26692 [startup+6.31404 s] /proc/loadavg: 1.00 1.00 1.00 2/35 15656 /proc/meminfo: memFree=353408/1048576 swapFree=0/0 [pid=15639] ppid=15638 vsize=2596 CPUtime=2.05 /proc/15639/stat : 15639 (aspcud-paranoid) S 15638 15639 4778 34817 4778 4202496 656 21050 0 0 0 0 194 11 15 0 1 0 10913628 2658304 299 1283457024 134512640 135304128 4290254240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15639/statm: 649 299 251 194 0 36 0 [pid=15653] ppid=15639 vsize=24096 CPUtime=4.13 /proc/15653/stat : 15653 (clasp) R 15639 15639 4778 34817 4778 4202496 6883 0 0 0 407 6 0 0 25 0 1 0 10913630 24674304 5791 1283457024 134512640 136285277 4294834624 18446744073709551615 134669904 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15653/statm: 6024 5791 234 433 0 5589 0 Current children cumulated CPU time (s) 6.18 Current children cumulated vsize (KiB) 26692 [startup+12.7155 s] /proc/loadavg: 1.00 1.00 1.00 2/35 15656 /proc/meminfo: memFree=353408/1048576 swapFree=0/0 [pid=15639] ppid=15638 vsize=2596 CPUtime=2.05 /proc/15639/stat : 15639 (aspcud-paranoid) S 15638 15639 4778 34817 4778 4202496 656 21050 0 0 0 0 194 11 15 0 1 0 10913628 2658304 299 1283457024 134512640 135304128 4290254240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15639/statm: 649 299 251 194 0 36 0 [pid=15653] ppid=15639 vsize=24096 CPUtime=10.53 /proc/15653/stat : 15653 (clasp) R 15639 15639 4778 34817 4778 4202496 6883 0 0 0 1047 6 0 0 25 0 1 0 10913630 24674304 5791 1283457024 134512640 136285277 4294834624 18446744073709551615 134931349 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15653/statm: 6024 5791 234 433 0 5589 0 Current children cumulated CPU time (s) 12.58 Current children cumulated vsize (KiB) 26692 Solver just ended. Dumping a history of the last processes samples [startup+12.8155 s] /proc/loadavg: 1.00 1.00 1.00 2/35 15656 /proc/meminfo: memFree=353408/1048576 swapFree=0/0 [pid=15639] ppid=15638 vsize=2596 CPUtime=2.05 /proc/15639/stat : 15639 (aspcud-paranoid) S 15638 15639 4778 34817 4778 4202496 656 21050 0 0 0 0 194 11 15 0 1 0 10913628 2658304 299 1283457024 134512640 135304128 4290254240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15639/statm: 649 299 251 194 0 36 0 [pid=15653] ppid=15639 vsize=24096 CPUtime=10.63 /proc/15653/stat : 15653 (clasp) R 15639 15639 4778 34817 4778 4202496 6883 0 0 0 1057 6 0 0 25 0 1 0 10913630 24674304 5791 1283457024 134512640 136285277 4294834624 18446744073709551615 134723339 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15653/statm: 6024 5791 234 433 0 5589 0 Current children cumulated CPU time (s) 12.68 Current children cumulated vsize (KiB) 26692 [startup+14.4058 s] /proc/loadavg: 1.00 1.00 1.00 2/35 15656 /proc/meminfo: memFree=353408/1048576 swapFree=0/0 [pid=15639] ppid=15638 vsize=2596 CPUtime=2.05 /proc/15639/stat : 15639 (aspcud-paranoid) S 15638 15639 4778 34817 4778 4202496 656 21050 0 0 0 0 194 11 15 0 1 0 10913628 2658304 299 1283457024 134512640 135304128 4290254240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15639/statm: 649 299 251 194 0 36 0 [pid=15653] ppid=15639 vsize=24096 CPUtime=12.22 /proc/15653/stat : 15653 (clasp) R 15639 15639 4778 34817 4778 4202496 6883 0 0 0 1216 6 0 0 25 0 1 0 10913630 24674304 5791 1283457024 134512640 136285277 4294834624 18446744073709551615 134733711 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15653/statm: 6024 5791 234 433 0 5589 0 Current children cumulated CPU time (s) 14.27 Current children cumulated vsize (KiB) 26692 [startup+15.206 s] /proc/loadavg: 1.00 1.00 1.00 2/35 15656 /proc/meminfo: memFree=353408/1048576 swapFree=0/0 [pid=15639] ppid=15638 vsize=2596 CPUtime=2.05 /proc/15639/stat : 15639 (aspcud-paranoid) S 15638 15639 4778 34817 4778 4202496 656 21050 0 0 0 0 194 11 15 0 1 0 10913628 2658304 299 1283457024 134512640 135304128 4290254240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15639/statm: 649 299 251 194 0 36 0 [pid=15653] ppid=15639 vsize=24096 CPUtime=13.02 /proc/15653/stat : 15653 (clasp) R 15639 15639 4778 34817 4778 4202496 6883 0 0 0 1296 6 0 0 25 0 1 0 10913630 24674304 5791 1283457024 134512640 136285277 4294834624 18446744073709551615 134733725 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15653/statm: 6024 5791 234 433 0 5589 0 Current children cumulated CPU time (s) 15.07 Current children cumulated vsize (KiB) 26692 [startup+15.406 s] /proc/loadavg: 1.00 1.00 1.00 2/35 15656 /proc/meminfo: memFree=353408/1048576 swapFree=0/0 [pid=15639] ppid=15638 vsize=2596 CPUtime=2.05 /proc/15639/stat : 15639 (aspcud-paranoid) S 15638 15639 4778 34817 4778 4202496 656 21050 0 0 0 0 194 11 15 0 1 0 10913628 2658304 299 1283457024 134512640 135304128 4290254240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15639/statm: 649 299 251 194 0 36 0 [pid=15653] ppid=15639 vsize=24096 CPUtime=13.22 /proc/15653/stat : 15653 (clasp) R 15639 15639 4778 34817 4778 4202496 6883 0 0 0 1316 6 0 0 25 0 1 0 10913630 24674304 5791 1283457024 134512640 136285277 4294834624 18446744073709551615 134959792 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15653/statm: 6024 5791 234 433 0 5589 0 Current children cumulated CPU time (s) 15.27 Current children cumulated vsize (KiB) 26692 [startup+15.506 s] /proc/loadavg: 1.00 1.00 1.00 2/35 15656 /proc/meminfo: memFree=353408/1048576 swapFree=0/0 [pid=15639] ppid=15638 vsize=2596 CPUtime=2.05 /proc/15639/stat : 15639 (aspcud-paranoid) S 15638 15639 4778 34817 4778 4202496 656 21050 0 0 0 0 194 11 15 0 1 0 10913628 2658304 299 1283457024 134512640 135304128 4290254240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15639/statm: 649 299 251 194 0 36 0 [pid=15653] ppid=15639 vsize=24096 CPUtime=13.32 /proc/15653/stat : 15653 (clasp) R 15639 15639 4778 34817 4778 4202496 6883 0 0 0 1326 6 0 0 25 0 1 0 10913630 24674304 5791 1283457024 134512640 136285277 4294834624 18446744073709551615 134733711 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15653/statm: 6024 5791 234 433 0 5589 0 Current children cumulated CPU time (s) 15.37 Current children cumulated vsize (KiB) 26692 Child status: 0 Real time (s): 15.5633 CPU time (s): 15.437 CPU user time (s): 15.253 CPU system time (s): 0.184011 CPU usage (%): 99.1884 Max. virtual memory (cumulated for all children) (KiB): 51580 getrusage(RUSAGE_CHILDREN,...) data: user time used= 15.253 system time used= 0.184011 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 32231 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= 862 involuntary context switches= 808 runsolver used 0 second user time and 0 second system time The end