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/201108300820/aspuncud-user-1.0/cff22854-9512-11e0-8001-00163e1e087d.cudf.dudf-real.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-real//cff22854-9512-11e0-8001-00163e1e087d.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/cff22854-9512-11e0-8001-00163e1e087d.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.99 0.97 0.99 1/34 15931 /proc/meminfo: memFree=944212/1048576 swapFree=0/0 [pid=15931] ppid=15930 vsize=3016 CPUtime=0 /proc/15931/stat : 15931 (runsolver) D 15930 15931 2160 34817 2160 4202560 72 0 0 0 0 0 0 0 25 0 1 0 58193654 3088384 93 1283457024 134512640 134586868 4289014608 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/15931/statm: 754 93 62 19 0 53 0 [startup+0.110764 s] /proc/loadavg: 0.99 0.97 0.99 1/34 15931 /proc/meminfo: memFree=944212/1048576 swapFree=0/0 [pid=15931] ppid=15930 vsize=2592 CPUtime=0 /proc/15931/stat : 15931 (aspuncud-user-1) S 15930 15931 2160 34817 2160 4202496 570 1519 0 3 0 0 0 0 25 0 1 0 58193654 2654208 297 1283457024 134512640 135304128 4290059552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15931/statm: 648 297 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.206764 s] /proc/loadavg: 0.99 0.97 0.99 1/34 15931 /proc/meminfo: memFree=944212/1048576 swapFree=0/0 [pid=15931] ppid=15930 vsize=2592 CPUtime=0 /proc/15931/stat : 15931 (aspuncud-user-1) S 15930 15931 2160 34817 2160 4202496 570 1519 0 3 0 0 0 0 25 0 1 0 58193654 2654208 297 1283457024 134512640 135304128 4290059552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15931/statm: 648 297 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.306756 s] /proc/loadavg: 0.99 0.97 0.99 1/34 15931 /proc/meminfo: memFree=944212/1048576 swapFree=0/0 [pid=15931] ppid=15930 vsize=2592 CPUtime=0 /proc/15931/stat : 15931 (aspuncud-user-1) S 15930 15931 2160 34817 2160 4202496 570 1519 0 3 0 0 0 0 25 0 1 0 58193654 2654208 297 1283457024 134512640 135304128 4290059552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15931/statm: 648 297 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.7114 s] /proc/loadavg: 0.99 0.97 0.99 1/34 15931 /proc/meminfo: memFree=944212/1048576 swapFree=0/0 [pid=15931] ppid=15930 vsize=2592 CPUtime=0 /proc/15931/stat : 15931 (aspuncud-user-1) S 15930 15931 2160 34817 2160 4202496 570 1519 0 3 0 0 0 0 25 0 1 0 58193654 2654208 297 1283457024 134512640 135304128 4290059552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15931/statm: 648 297 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+1.51159 s] /proc/loadavg: 0.99 0.97 0.99 2/38 15942 /proc/meminfo: memFree=916300/1048576 swapFree=0/0 [pid=15931] ppid=15930 vsize=2592 CPUtime=0 /proc/15931/stat : 15931 (aspuncud-user-1) S 15930 15931 2160 34817 2160 4202496 570 1519 0 3 0 0 0 0 25 0 1 0 58193654 2654208 297 1283457024 134512640 135304128 4290059552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15931/statm: 648 297 251 194 0 35 0 [pid=15940] ppid=15931 vsize=3444 CPUtime=0 /proc/15940/stat : 15940 (unclasp) S 15931 15931 2160 34817 2160 4202496 402 0 5 0 0 0 0 0 24 0 1 0 58193658 3526656 272 1283457024 134512640 135121179 4293669664 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/15940/statm: 861 272 240 149 0 52 0 [pid=15941] ppid=15931 vsize=2692 CPUtime=0 /proc/15941/stat : 15941 (gringo) S 15931 15931 2160 34817 2160 4202496 385 0 23 0 0 0 0 0 23 0 1 0 58193658 2756608 281 1283457024 134512640 137056543 4287726432 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/15941/statm: 673 281 252 622 0 48 0 [pid=15942] ppid=15931 vsize=26772 CPUtime=1.26 /proc/15942/stat : 15942 (cudf2lp) R 15931 15931 2160 34817 2160 4202496 7687 0 15 0 126 0 0 0 25 0 1 0 58193658 27414528 6110 1283457024 134512640 135786343 4293669536 18446744073709551615 135199337 0 0 6 0 0 0 0 17 0 0 0 0 /proc/15942/statm: 6693 6110 128 311 0 6380 0 Current children cumulated CPU time (s) 1.26 Current children cumulated vsize (KiB) 35500 [startup+3.11198 s] /proc/loadavg: 0.99 0.97 0.99 3/38 15942 /proc/meminfo: memFree=891440/1048576 swapFree=0/0 [pid=15931] ppid=15930 vsize=2592 CPUtime=0 /proc/15931/stat : 15931 (aspuncud-user-1) S 15930 15931 2160 34817 2160 4202496 570 1519 0 3 0 0 0 0 25 0 1 0 58193654 2654208 297 1283457024 134512640 135304128 4290059552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15931/statm: 648 297 251 194 0 35 0 [pid=15940] ppid=15931 vsize=20960 CPUtime=0.07 /proc/15940/stat : 15940 (unclasp) R 15931 15931 2160 34817 2160 4202496 5467 0 6 0 6 1 0 0 18 0 1 0 58193658 21463040 4680 1283457024 134512640 135121179 4293669664 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15940/statm: 5240 4680 275 149 0 4431 0 [pid=15941] ppid=15931 vsize=29544 CPUtime=0.97 /proc/15941/stat : 15941 (gringo) R 15931 15931 2160 34817 2160 4202496 8850 0 23 0 95 2 0 0 18 0 1 0 58193658 30253056 5452 1283457024 134512640 137056543 4287726432 18446744073709551615 134914507 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15941/statm: 7386 5452 253 622 0 6761 0 [pid=15942] ppid=15931 vsize=37744 CPUtime=1.78 /proc/15942/stat : 15942 (cudf2lp) R 15931 15931 2160 34817 2160 4202496 11916 0 15 0 176 2 0 0 25 0 1 0 58193658 38649856 9240 1283457024 134512640 135786343 4293669536 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/15942/statm: 9436 9240 139 311 0 9123 0 Current children cumulated CPU time (s) 2.82 Current children cumulated vsize (KiB) 90840 [startup+6.31266 s] /proc/loadavg: 1.07 0.99 0.99 3/37 15942 /proc/meminfo: memFree=816196/1048576 swapFree=0/0 [pid=15931] ppid=15930 vsize=2592 CPUtime=2.18 /proc/15931/stat : 15931 (aspuncud-user-1) S 15930 15931 2160 34817 2160 4202496 570 13438 0 18 0 0 214 4 18 0 1 0 58193654 2654208 297 1283457024 134512640 135304128 4290059552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15931/statm: 648 297 251 194 0 35 0 [pid=15940] ppid=15931 vsize=64580 CPUtime=0.42 /proc/15940/stat : 15940 (unclasp) R 15931 15931 2160 34817 2160 4202496 17909 0 6 0 36 6 0 0 18 0 1 0 58193658 66129920 15407 1283457024 134512640 135121179 4293669664 18446744073709551615 4157620963 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15940/statm: 16145 15407 277 149 0 15336 0 [pid=15941] ppid=15931 vsize=101312 CPUtime=3.43 /proc/15941/stat : 15941 (gringo) R 15931 15931 2160 34817 2160 4202496 32549 0 23 0 333 10 0 0 19 0 1 0 58193658 103743488 20998 1283457024 134512640 137056543 4287726432 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15941/statm: 25328 20998 268 622 0 24703 0 Current children cumulated CPU time (s) 6.03 Current children cumulated vsize (KiB) 168484 [startup+12.7059 s] /proc/loadavg: 1.07 0.99 0.99 2/36 15942 /proc/meminfo: memFree=836176/1048576 swapFree=0/0 [pid=15931] ppid=15930 vsize=2592 CPUtime=6.5 /proc/15931/stat : 15931 (aspuncud-user-1) S 15930 15931 2160 34817 2160 4202496 570 54453 0 41 0 0 630 20 18 0 1 0 58193654 2654208 297 1283457024 134512640 135304128 4290059552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15931/statm: 648 297 251 194 0 35 0 [pid=15940] ppid=15931 vsize=110000 CPUtime=5.91 /proc/15940/stat : 15940 (unclasp) R 15931 15931 2160 34817 2160 4202496 104663 0 7 0 552 39 0 0 25 0 1 0 58193658 112640000 25572 1283457024 134512640 135121179 4293669664 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15940/statm: 27500 25572 319 149 0 26691 0 Current children cumulated CPU time (s) 12.41 Current children cumulated vsize (KiB) 112592 [startup+25.5097 s] /proc/loadavg: 1.05 0.99 0.99 2/36 15942 /proc/meminfo: memFree=834812/1048576 swapFree=0/0 [pid=15931] ppid=15930 vsize=2592 CPUtime=6.5 /proc/15931/stat : 15931 (aspuncud-user-1) S 15930 15931 2160 34817 2160 4202496 570 54453 0 41 0 0 630 20 18 0 1 0 58193654 2654208 297 1283457024 134512640 135304128 4290059552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15931/statm: 648 297 251 194 0 35 0 [pid=15940] ppid=15931 vsize=109860 CPUtime=18.68 /proc/15940/stat : 15940 (unclasp) R 15931 15931 2160 34817 2160 4202496 308577 0 7 0 1733 135 0 0 25 0 1 0 58193658 112496640 25544 1283457024 134512640 135121179 4293669664 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15940/statm: 27465 25544 319 149 0 26656 0 Current children cumulated CPU time (s) 25.18 Current children cumulated vsize (KiB) 112452 [startup+51.1145 s] /proc/loadavg: 1.03 0.99 0.99 2/35 15942 /proc/meminfo: memFree=833828/1048576 swapFree=0/0 [pid=15931] ppid=15930 vsize=2592 CPUtime=6.5 /proc/15931/stat : 15931 (aspuncud-user-1) S 15930 15931 2160 34817 2160 4202496 570 54453 0 41 0 0 630 20 18 0 1 0 58193654 2654208 297 1283457024 134512640 135304128 4290059552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15931/statm: 648 297 251 194 0 35 0 [pid=15940] ppid=15931 vsize=111280 CPUtime=44.25 /proc/15940/stat : 15940 (unclasp) R 15931 15931 2160 34817 2160 4202496 692105 0 7 0 4138 287 0 0 25 0 1 0 58193658 113950720 25915 1283457024 134512640 135121179 4293669664 18446744073709551615 134891813 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15940/statm: 27820 25915 321 149 0 27011 0 Current children cumulated CPU time (s) 50.75 Current children cumulated vsize (KiB) 113872 [startup+102.306 s] /proc/loadavg: 1.01 0.99 0.99 2/35 15942 /proc/meminfo: memFree=836060/1048576 swapFree=0/0 [pid=15931] ppid=15930 vsize=2592 CPUtime=6.5 /proc/15931/stat : 15931 (aspuncud-user-1) S 15930 15931 2160 34817 2160 4202496 570 54453 0 41 0 0 630 20 18 0 1 0 58193654 2654208 297 1283457024 134512640 135304128 4290059552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15931/statm: 648 297 251 194 0 35 0 [pid=15940] ppid=15931 vsize=113912 CPUtime=95.32 /proc/15940/stat : 15940 (unclasp) R 15931 15931 2160 34817 2160 4202496 1449753 0 7 0 8913 619 0 0 25 0 1 0 58193658 116645888 26186 1283457024 134512640 135121179 4293669664 18446744073709551615 134990541 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15940/statm: 28478 26186 321 149 0 27669 0 Current children cumulated CPU time (s) 101.82 Current children cumulated vsize (KiB) 116504 [startup+162.311 s] /proc/loadavg: 1.06 1.00 1.00 2/35 15942 /proc/meminfo: memFree=837796/1048576 swapFree=0/0 [pid=15931] ppid=15930 vsize=2592 CPUtime=6.5 /proc/15931/stat : 15931 (aspuncud-user-1) S 15930 15931 2160 34817 2160 4202496 570 54453 0 41 0 0 630 20 18 0 1 0 58193654 2654208 297 1283457024 134512640 135304128 4290059552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15931/statm: 648 297 251 194 0 35 0 [pid=15940] ppid=15931 vsize=109880 CPUtime=155.21 /proc/15940/stat : 15940 (unclasp) R 15931 15931 2160 34817 2160 4202496 2329771 0 7 0 14526 995 0 0 25 0 1 0 58193658 112517120 25602 1283457024 134512640 135121179 4293669664 18446744073709551615 134713294 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15940/statm: 27470 25602 321 149 0 26661 0 Current children cumulated CPU time (s) 161.71 Current children cumulated vsize (KiB) 112472 [startup+222.306 s] /proc/loadavg: 1.02 1.00 1.00 2/35 15942 /proc/meminfo: memFree=837672/1048576 swapFree=0/0 [pid=15931] ppid=15930 vsize=2592 CPUtime=6.5 /proc/15931/stat : 15931 (aspuncud-user-1) S 15930 15931 2160 34817 2160 4202496 570 54453 0 41 0 0 630 20 18 0 1 0 58193654 2654208 297 1283457024 134512640 135304128 4290059552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15931/statm: 648 297 251 194 0 35 0 [pid=15940] ppid=15931 vsize=112516 CPUtime=215.1 /proc/15940/stat : 15940 (unclasp) R 15931 15931 2160 34817 2160 4202496 3188855 0 7 0 20153 1357 0 0 25 0 1 0 58193658 115216384 26282 1283457024 134512640 135121179 4293669664 18446744073709551615 134981267 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15940/statm: 28129 26282 321 149 0 27320 0 Current children cumulated CPU time (s) 221.6 Current children cumulated vsize (KiB) 115108 [startup+282.31 s] /proc/loadavg: 1.00 1.00 1.00 2/37 15945 /proc/meminfo: memFree=835664/1048576 swapFree=0/0 [pid=15931] ppid=15930 vsize=2592 CPUtime=6.5 /proc/15931/stat : 15931 (aspuncud-user-1) S 15930 15931 2160 34817 2160 4202496 570 54453 0 41 0 0 630 20 18 0 1 0 58193654 2654208 297 1283457024 134512640 135304128 4290059552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15931/statm: 648 297 251 194 0 35 0 [pid=15940] ppid=15931 vsize=109896 CPUtime=274.99 /proc/15940/stat : 15940 (unclasp) R 15931 15931 2160 34817 2160 4202496 4033465 0 7 0 25797 1702 0 0 25 0 1 0 58193658 112533504 25643 1283457024 134512640 135121179 4293669664 18446744073709551615 134713280 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15940/statm: 27474 25643 321 149 0 26665 0 Current children cumulated CPU time (s) 281.49 Current children cumulated vsize (KiB) 112488 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.904 s] /proc/loadavg: 1.00 1.00 1.00 2/37 15946 /proc/meminfo: memFree=835664/1048576 swapFree=0/0 [pid=15931] ppid=15930 vsize=2592 CPUtime=6.5 /proc/15931/stat : 15931 (aspuncud-user-1) S 15930 15931 2160 34817 2160 4202496 570 54453 0 41 0 0 630 20 18 0 1 0 58193654 2654208 297 1283457024 134512640 135304128 4290059552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15931/statm: 648 297 251 194 0 35 0 [pid=15940] ppid=15931 vsize=111340 CPUtime=283.58 /proc/15940/stat : 15940 (unclasp) R 15931 15931 2160 34817 2160 4202496 4155878 0 7 0 26608 1750 0 0 25 0 1 0 58193658 114012160 26007 1283457024 134512640 135121179 4293669664 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15940/statm: 27835 26007 321 149 0 27026 0 Current children cumulated CPU time (s) 290.08 Current children cumulated vsize (KiB) 113932 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.904 s] /proc/loadavg: 1.00 1.00 1.00 2/37 15946 /proc/meminfo: memFree=835664/1048576 swapFree=0/0 [pid=15931] ppid=15930 vsize=2592 CPUtime=6.5 /proc/15931/stat : 15931 (aspuncud-user-1) S 15930 15931 2160 34817 2160 4202496 570 54453 0 41 0 0 630 20 18 0 1 0 58193654 2654208 297 1283457024 134512640 135304128 4290059552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15931/statm: 648 297 251 194 0 35 0 [pid=15940] ppid=15931 vsize=111340 CPUtime=283.58 /proc/15940/stat : 15940 (unclasp) R 15931 15931 2160 34817 2160 4202496 4155878 0 7 0 26608 1750 0 0 25 0 1 0 58193658 114012160 26007 1283457024 134512640 135121179 4293669664 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15940/statm: 27835 26007 321 149 0 27026 0 Current children cumulated CPU time (s) 290.08 Current children cumulated vsize (KiB) 113932 Child status: 0 Real time (s): 290.947 CPU time (s): 290.11 CPU user time (s): 272.389 CPU system time (s): 17.7211 CPU usage (%): 99.7122 Max. virtual memory (cumulated for all children) (KiB): 216816 getrusage(RUSAGE_CHILDREN,...) data: user time used= 272.389 system time used= 17.7211 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 4213278 page faults= 50 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 7844 involuntary context switches= 9775 runsolver used 0 second user time and 0 second system time The end