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/cb0e73b0-0ffd-11df-9e59-00163e2c8d72.cudf.dudf-real.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-real//cb0e73b0-0ffd-11df-9e59-00163e2c8d72.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/cb0e73b0-0ffd-11df-9e59-00163e2c8d72.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: 1.02 1.00 1.00 5/35 15769 /proc/meminfo: memFree=916192/1048576 swapFree=0/0 [pid=15767] ppid=15766 vsize=2588 CPUtime=0 /proc/15767/stat : 15767 (aspuncud-user-1) S 15766 15767 2160 34817 2160 4202496 374 0 0 0 0 0 0 0 18 0 1 0 58128789 2650112 280 1283457024 134512640 135304128 4292863952 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/15767/statm: 647 280 234 194 0 34 0 [pid=15768] ppid=15767 vsize=2588 CPUtime=0 /proc/15768/stat : 15768 (aspuncud-user-1) R 15767 15767 2160 34817 2160 4202560 110 0 0 0 0 0 0 0 25 0 1 0 58128789 2650112 133 1283457024 134512640 135304128 4292863952 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/15768/statm: 647 133 86 194 0 34 0 [pid=15769] ppid=15768 vsize=2588 CPUtime=0 /proc/15769/stat : 15769 (aspuncud-user-1) R 15768 15767 2160 34817 2160 4202560 0 0 0 0 0 0 0 0 25 0 1 0 58128789 2650112 47 1283457024 134512640 135304128 4292863952 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/15769/statm: 647 47 0 194 0 34 0 [startup+0.17868 s] /proc/loadavg: 1.02 1.00 1.00 5/35 15769 /proc/meminfo: memFree=916192/1048576 swapFree=0/0 [pid=15767] ppid=15766 vsize=2592 CPUtime=0 /proc/15767/stat : 15767 (aspuncud-user-1) S 15766 15767 2160 34817 2160 4202496 573 1521 0 0 0 0 0 0 25 0 1 0 58128789 2654208 298 1283457024 134512640 135304128 4292863952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15767/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.208784 s] /proc/loadavg: 1.02 1.00 1.00 5/35 15769 /proc/meminfo: memFree=916192/1048576 swapFree=0/0 [pid=15767] ppid=15766 vsize=2592 CPUtime=0 /proc/15767/stat : 15767 (aspuncud-user-1) S 15766 15767 2160 34817 2160 4202496 573 1521 0 0 0 0 0 0 25 0 1 0 58128789 2654208 298 1283457024 134512640 135304128 4292863952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15767/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.308715 s] /proc/loadavg: 1.02 1.00 1.00 5/35 15769 /proc/meminfo: memFree=916192/1048576 swapFree=0/0 [pid=15767] ppid=15766 vsize=2592 CPUtime=0 /proc/15767/stat : 15767 (aspuncud-user-1) S 15766 15767 2160 34817 2160 4202496 573 1521 0 0 0 0 0 0 25 0 1 0 58128789 2654208 298 1283457024 134512640 135304128 4292863952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15767/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.708781 s] /proc/loadavg: 1.02 1.00 1.00 5/35 15769 /proc/meminfo: memFree=916192/1048576 swapFree=0/0 [pid=15767] ppid=15766 vsize=2592 CPUtime=0 /proc/15767/stat : 15767 (aspuncud-user-1) S 15766 15767 2160 34817 2160 4202496 573 1521 0 0 0 0 0 0 25 0 1 0 58128789 2654208 298 1283457024 134512640 135304128 4292863952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15767/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+1.50891 s] /proc/loadavg: 1.02 1.00 1.00 3/37 15778 /proc/meminfo: memFree=884744/1048576 swapFree=0/0 [pid=15767] ppid=15766 vsize=2592 CPUtime=0 /proc/15767/stat : 15767 (aspuncud-user-1) S 15766 15767 2160 34817 2160 4202496 573 1521 0 0 0 0 0 0 25 0 1 0 58128789 2654208 298 1283457024 134512640 135304128 4292863952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15767/statm: 648 298 251 194 0 35 0 [pid=15776] ppid=15767 vsize=13272 CPUtime=0.04 /proc/15776/stat : 15776 (unclasp) S 15767 15767 2160 34817 2160 4202496 3224 0 0 0 3 1 0 0 18 0 1 0 58128790 13590528 2702 1283457024 134512640 135121179 4289926560 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/15776/statm: 3318 2702 275 149 0 2509 0 [pid=15777] ppid=15767 vsize=16928 CPUtime=0.53 /proc/15777/stat : 15777 (gringo) R 15767 15767 2160 34817 2160 4202496 4770 0 0 0 50 3 0 0 18 0 1 0 58128790 17334272 3339 1283457024 134512640 137056543 4287126144 18446744073709551615 136268293 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15777/statm: 4232 3339 253 622 0 3607 0 [pid=15778] ppid=15767 vsize=22720 CPUtime=0.9 /proc/15778/stat : 15778 (cudf2lp) R 15767 15767 2160 34817 2160 4202496 6925 0 0 0 90 0 0 0 25 0 1 0 58128790 23265280 5502 1283457024 134512640 135786343 4289402144 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/15778/statm: 5680 5502 139 311 0 5367 0 Current children cumulated CPU time (s) 1.47 Current children cumulated vsize (KiB) 55512 [startup+3.10932 s] /proc/loadavg: 1.02 1.00 1.00 3/37 15778 /proc/meminfo: memFree=851760/1048576 swapFree=0/0 [pid=15767] ppid=15766 vsize=2592 CPUtime=1.05 /proc/15767/stat : 15767 (aspuncud-user-1) S 15766 15767 2160 34817 2160 4202496 573 8449 0 0 0 0 104 1 18 0 1 0 58128789 2654208 298 1283457024 134512640 135304128 4292863952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15767/statm: 648 298 251 194 0 35 0 [pid=15776] ppid=15767 vsize=36924 CPUtime=0.31 /proc/15776/stat : 15776 (unclasp) R 15767 15767 2160 34817 2160 4202496 9759 0 0 0 28 3 0 0 18 0 1 0 58128790 37810176 8559 1283457024 134512640 135121179 4289926560 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15776/statm: 9231 8559 277 149 0 8422 0 [pid=15777] ppid=15767 vsize=58576 CPUtime=1.71 /proc/15777/stat : 15777 (gringo) R 15767 15767 2160 34817 2160 4202496 17180 0 0 0 164 7 0 0 18 0 1 0 58128790 59981824 12924 1283457024 134512640 137056543 4287126144 18446744073709551615 134582055 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15777/statm: 14644 12924 268 622 0 14019 0 Current children cumulated CPU time (s) 3.07 Current children cumulated vsize (KiB) 98092 [startup+6.31265 s] /proc/loadavg: 1.02 1.00 1.00 2/35 15778 /proc/meminfo: memFree=865812/1048576 swapFree=0/0 [pid=15767] ppid=15766 vsize=2592 CPUtime=3.08 /proc/15767/stat : 15767 (aspuncud-user-1) S 15766 15767 2160 34817 2160 4202496 573 27249 0 0 0 0 295 13 18 0 1 0 58128789 2654208 298 1283457024 134512640 135304128 4292863952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15767/statm: 648 298 251 194 0 35 0 [pid=15776] ppid=15767 vsize=55808 CPUtime=3.18 /proc/15776/stat : 15776 (unclasp) R 15767 15767 2160 34817 2160 4202496 48849 0 0 0 298 20 0 0 24 0 1 0 58128790 57147392 12716 1283457024 134512640 135121179 4289926560 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15776/statm: 13952 12716 321 149 0 13143 0 Current children cumulated CPU time (s) 6.26 Current children cumulated vsize (KiB) 58400 [startup+12.7066 s] /proc/loadavg: 1.02 1.00 1.00 2/35 15778 /proc/meminfo: memFree=865440/1048576 swapFree=0/0 [pid=15767] ppid=15766 vsize=2592 CPUtime=3.08 /proc/15767/stat : 15767 (aspuncud-user-1) S 15766 15767 2160 34817 2160 4202496 573 27249 0 0 0 0 295 13 18 0 1 0 58128789 2654208 298 1283457024 134512640 135304128 4292863952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15767/statm: 648 298 251 194 0 35 0 [pid=15776] ppid=15767 vsize=56680 CPUtime=9.57 /proc/15776/stat : 15776 (unclasp) R 15767 15767 2160 34817 2160 4202496 131833 0 0 0 895 62 0 0 25 0 1 0 58128790 58040320 12943 1283457024 134512640 135121179 4289926560 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15776/statm: 14170 12943 321 149 0 13361 0 Current children cumulated CPU time (s) 12.65 Current children cumulated vsize (KiB) 59272 [startup+25.5044 s] /proc/loadavg: 1.01 1.00 1.00 2/35 15778 /proc/meminfo: memFree=866060/1048576 swapFree=0/0 [pid=15767] ppid=15766 vsize=2592 CPUtime=3.08 /proc/15767/stat : 15767 (aspuncud-user-1) S 15766 15767 2160 34817 2160 4202496 573 27249 0 0 0 0 295 13 18 0 1 0 58128789 2654208 298 1283457024 134512640 135304128 4292863952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15767/statm: 648 298 251 194 0 35 0 [pid=15776] ppid=15767 vsize=56280 CPUtime=22.32 /proc/15776/stat : 15776 (unclasp) R 15767 15767 2160 34817 2160 4202496 283384 0 0 0 2107 125 0 0 25 0 1 0 58128790 57630720 12835 1283457024 134512640 135121179 4289926560 18446744073709551615 4159640645 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15776/statm: 14070 12835 321 149 0 13261 0 Current children cumulated CPU time (s) 25.4 Current children cumulated vsize (KiB) 58872 [startup+51.1053 s] /proc/loadavg: 1.01 1.00 1.00 2/35 15778 /proc/meminfo: memFree=865068/1048576 swapFree=0/0 [pid=15767] ppid=15766 vsize=2592 CPUtime=3.08 /proc/15767/stat : 15767 (aspuncud-user-1) S 15766 15767 2160 34817 2160 4202496 573 27249 0 0 0 0 295 13 18 0 1 0 58128789 2654208 298 1283457024 134512640 135304128 4292863952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15767/statm: 648 298 251 194 0 35 0 [pid=15776] ppid=15767 vsize=55820 CPUtime=47.82 /proc/15776/stat : 15776 (unclasp) R 15767 15767 2160 34817 2160 4202496 572934 0 0 0 4540 242 0 0 25 0 1 0 58128790 57159680 12754 1283457024 134512640 135121179 4289926560 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15776/statm: 13955 12754 321 149 0 13146 0 Current children cumulated CPU time (s) 50.9 Current children cumulated vsize (KiB) 58412 [startup+102.309 s] /proc/loadavg: 1.00 1.00 1.00 2/35 15778 /proc/meminfo: memFree=864944/1048576 swapFree=0/0 [pid=15767] ppid=15766 vsize=2592 CPUtime=3.08 /proc/15767/stat : 15767 (aspuncud-user-1) S 15766 15767 2160 34817 2160 4202496 573 27249 0 0 0 0 295 13 18 0 1 0 58128789 2654208 298 1283457024 134512640 135304128 4292863952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15767/statm: 648 298 251 194 0 35 0 [pid=15776] ppid=15767 vsize=56748 CPUtime=98.9 /proc/15776/stat : 15776 (unclasp) R 15767 15767 2160 34817 2160 4202496 1134136 0 0 0 9378 512 0 0 25 0 1 0 58128790 58109952 13005 1283457024 134512640 135121179 4289926560 18446744073709551615 134977770 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15776/statm: 14187 13005 321 149 0 13378 0 Current children cumulated CPU time (s) 101.98 Current children cumulated vsize (KiB) 59340 [startup+162.31 s] /proc/loadavg: 1.00 1.00 1.00 2/37 15784 /proc/meminfo: memFree=864052/1048576 swapFree=0/0 [pid=15767] ppid=15766 vsize=2592 CPUtime=3.08 /proc/15767/stat : 15767 (aspuncud-user-1) S 15766 15767 2160 34817 2160 4202496 573 27249 0 0 0 0 295 13 18 0 1 0 58128789 2654208 298 1283457024 134512640 135304128 4292863952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15767/statm: 648 298 251 194 0 35 0 [pid=15776] ppid=15767 vsize=57660 CPUtime=158.8 /proc/15776/stat : 15776 (unclasp) R 15767 15767 2160 34817 2160 4202496 1759265 0 0 0 15098 782 0 0 25 0 1 0 58128790 59043840 13298 1283457024 134512640 135121179 4289926560 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15776/statm: 14415 13298 323 149 0 13606 0 Current children cumulated CPU time (s) 161.88 Current children cumulated vsize (KiB) 60252 [startup+222.306 s] /proc/loadavg: 1.00 1.00 1.00 2/36 15789 /proc/meminfo: memFree=831208/1048576 swapFree=0/0 [pid=15767] ppid=15766 vsize=2592 CPUtime=3.08 /proc/15767/stat : 15767 (aspuncud-user-1) S 15766 15767 2160 34817 2160 4202496 573 27249 0 0 0 0 295 13 18 0 1 0 58128789 2654208 298 1283457024 134512640 135304128 4292863952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15767/statm: 648 298 251 194 0 35 0 [pid=15776] ppid=15767 vsize=88696 CPUtime=218.6 /proc/15776/stat : 15776 (unclasp) R 15767 15767 2160 34817 2160 4202496 2261696 0 0 0 20841 1019 0 0 25 0 1 0 58128790 90824704 21217 1283457024 134512640 135121179 4289926560 18446744073709551615 134891399 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15776/statm: 22174 21217 323 149 0 21365 0 Current children cumulated CPU time (s) 221.68 Current children cumulated vsize (KiB) 91288 [startup+282.31 s] /proc/loadavg: 1.00 1.00 1.00 2/35 15789 /proc/meminfo: memFree=774424/1048576 swapFree=0/0 [pid=15767] ppid=15766 vsize=2592 CPUtime=3.08 /proc/15767/stat : 15767 (aspuncud-user-1) S 15766 15767 2160 34817 2160 4202496 573 27249 0 0 0 0 295 13 18 0 1 0 58128789 2654208 298 1283457024 134512640 135304128 4292863952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15767/statm: 648 298 251 194 0 35 0 [pid=15776] ppid=15767 vsize=146932 CPUtime=278.49 /proc/15776/stat : 15776 (unclasp) R 15767 15767 2160 34817 2160 4202496 2747040 0 0 0 26615 1234 0 0 25 0 1 0 58128790 150458368 35961 1283457024 134512640 135121179 4289926560 18446744073709551615 134891805 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15776/statm: 36733 35961 324 149 0 35924 0 Current children cumulated CPU time (s) 281.57 Current children cumulated vsize (KiB) 149524 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.813 s] /proc/loadavg: 1.00 1.00 1.00 2/35 15789 /proc/meminfo: memFree=761776/1048576 swapFree=0/0 [pid=15767] ppid=15766 vsize=2592 CPUtime=3.08 /proc/15767/stat : 15767 (aspuncud-user-1) S 15766 15767 2160 34817 2160 4202496 573 27249 0 0 0 0 295 13 18 0 1 0 58128789 2654208 298 1283457024 134512640 135304128 4292863952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15767/statm: 648 298 251 194 0 35 0 [pid=15776] ppid=15767 vsize=156680 CPUtime=286.99 /proc/15776/stat : 15776 (unclasp) R 15767 15767 2160 34817 2160 4202496 2800467 0 0 0 27443 1256 0 0 25 0 1 0 58128790 160440320 38453 1283457024 134512640 135121179 4289926560 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15776/statm: 39170 38453 324 149 0 38361 0 Current children cumulated CPU time (s) 290.07 Current children cumulated vsize (KiB) 159272 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.813 s] /proc/loadavg: 1.00 1.00 1.00 2/35 15789 /proc/meminfo: memFree=761776/1048576 swapFree=0/0 [pid=15767] ppid=15766 vsize=2592 CPUtime=3.08 /proc/15767/stat : 15767 (aspuncud-user-1) S 15766 15767 2160 34817 2160 4202496 573 27249 0 0 0 0 295 13 18 0 1 0 58128789 2654208 298 1283457024 134512640 135304128 4292863952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15767/statm: 648 298 251 194 0 35 0 [pid=15776] ppid=15767 vsize=156680 CPUtime=286.99 /proc/15776/stat : 15776 (unclasp) R 15767 15767 2160 34817 2160 4202496 2800467 0 0 0 27443 1256 0 0 25 0 1 0 58128790 160440320 38453 1283457024 134512640 135121179 4289926560 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15776/statm: 39170 38453 324 149 0 38361 0 Current children cumulated CPU time (s) 290.07 Current children cumulated vsize (KiB) 159272 Child status: 0 Real time (s): 290.837 CPU time (s): 290.118 CPU user time (s): 277.401 CPU system time (s): 12.7168 CPU usage (%): 99.7527 Max. virtual memory (cumulated for all children) (KiB): 159872 getrusage(RUSAGE_CHILDREN,...) data: user time used= 277.401 system time used= 12.7168 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 2830684 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= 3355 involuntary context switches= 6104 runsolver used 0 second user time and 0.008 second system time The end