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/ed1cc19e-51b7-11e0-8436-00163e1e087d.cudf.dudf-real.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-real//ed1cc19e-51b7-11e0-8436-00163e1e087d.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/ed1cc19e-51b7-11e0-8436-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: 1.00 1.03 1.00 1/33 18405 /proc/meminfo: memFree=945684/1048576 swapFree=0/0 [pid=18405] ppid=18404 vsize=3020 CPUtime=0 /proc/18405/stat : 18405 (runsolver) D 18404 18405 2160 34817 2160 4202560 72 0 0 0 0 0 0 0 25 0 1 0 59532303 3092480 94 1283457024 134512640 134586868 4287300016 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/18405/statm: 755 94 62 19 0 54 0 [startup+0.132539 s] /proc/loadavg: 1.00 1.03 1.00 1/33 18405 /proc/meminfo: memFree=945684/1048576 swapFree=0/0 [pid=18405] ppid=18404 vsize=2596 CPUtime=0 /proc/18405/stat : 18405 (aspuncud-user-1) S 18404 18405 2160 34817 2160 4202496 573 1516 0 3 0 0 0 0 25 0 1 0 59532303 2658304 298 1283457024 134512640 135304128 4292421472 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18405/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.204561 s] /proc/loadavg: 1.00 1.03 1.00 1/33 18405 /proc/meminfo: memFree=945684/1048576 swapFree=0/0 [pid=18405] ppid=18404 vsize=2596 CPUtime=0 /proc/18405/stat : 18405 (aspuncud-user-1) S 18404 18405 2160 34817 2160 4202496 573 1516 0 3 0 0 0 0 25 0 1 0 59532303 2658304 298 1283457024 134512640 135304128 4292421472 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18405/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.30908 s] /proc/loadavg: 1.00 1.03 1.00 1/33 18405 /proc/meminfo: memFree=945684/1048576 swapFree=0/0 [pid=18405] ppid=18404 vsize=2596 CPUtime=0 /proc/18405/stat : 18405 (aspuncud-user-1) S 18404 18405 2160 34817 2160 4202496 573 1516 0 3 0 0 0 0 25 0 1 0 59532303 2658304 298 1283457024 134512640 135304128 4292421472 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18405/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.709169 s] /proc/loadavg: 1.00 1.03 1.00 1/33 18405 /proc/meminfo: memFree=945684/1048576 swapFree=0/0 [pid=18405] ppid=18404 vsize=2596 CPUtime=0 /proc/18405/stat : 18405 (aspuncud-user-1) S 18404 18405 2160 34817 2160 4202496 573 1516 0 3 0 0 0 0 25 0 1 0 59532303 2658304 298 1283457024 134512640 135304128 4292421472 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18405/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50937 s] /proc/loadavg: 1.00 1.03 1.00 2/37 18416 /proc/meminfo: memFree=917516/1048576 swapFree=0/0 [pid=18405] ppid=18404 vsize=2596 CPUtime=0 /proc/18405/stat : 18405 (aspuncud-user-1) S 18404 18405 2160 34817 2160 4202496 573 1516 0 3 0 0 0 0 25 0 1 0 59532303 2658304 298 1283457024 134512640 135304128 4292421472 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18405/statm: 649 298 251 194 0 36 0 [pid=18414] ppid=18405 vsize=3440 CPUtime=0 /proc/18414/stat : 18414 (unclasp) S 18405 18405 2160 34817 2160 4202496 402 0 5 0 0 0 0 0 25 0 1 0 59532308 3522560 271 1283457024 134512640 135121179 4290009952 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/18414/statm: 860 271 240 149 0 51 0 [pid=18415] ppid=18405 vsize=2692 CPUtime=0 /proc/18415/stat : 18415 (gringo) S 18405 18405 2160 34817 2160 4202496 386 0 23 0 0 0 0 0 24 0 1 0 59532308 2756608 281 1283457024 134512640 137056543 4290010384 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/18415/statm: 673 281 252 622 0 48 0 [pid=18416] ppid=18405 vsize=38376 CPUtime=1.3 /proc/18416/stat : 18416 (cudf2lp) R 18405 18405 2160 34817 2160 4202496 10515 0 15 0 127 3 0 0 25 0 1 0 59532308 39297024 8888 1283457024 134512640 135786343 4287540720 18446744073709551615 135208238 0 0 6 0 0 0 0 17 0 0 0 0 /proc/18416/statm: 9594 8888 135 311 0 9281 0 Current children cumulated CPU time (s) 1.3 Current children cumulated vsize (KiB) 47104 [startup+3.10971 s] /proc/loadavg: 1.00 1.03 1.00 3/37 18416 /proc/meminfo: memFree=889184/1048576 swapFree=0/0 [pid=18405] ppid=18404 vsize=2596 CPUtime=0 /proc/18405/stat : 18405 (aspuncud-user-1) S 18404 18405 2160 34817 2160 4202496 573 1516 0 3 0 0 0 0 25 0 1 0 59532303 2658304 298 1283457024 134512640 135304128 4292421472 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18405/statm: 649 298 251 194 0 36 0 [pid=18414] ppid=18405 vsize=24936 CPUtime=0.11 /proc/18414/stat : 18414 (unclasp) S 18405 18405 2160 34817 2160 4202496 6743 0 6 0 7 4 0 0 18 0 1 0 59532308 25534464 5549 1283457024 134512640 135121179 4290009952 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/18414/statm: 6234 5549 275 149 0 5425 0 [pid=18415] ppid=18405 vsize=32492 CPUtime=1.19 /proc/18415/stat : 18415 (gringo) S 18405 18405 2160 34817 2160 4202496 10016 0 23 0 111 8 0 0 18 0 1 0 59532308 33271808 6714 1283457024 134512640 137056543 4290010384 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/18415/statm: 8123 6714 253 622 0 7498 0 [pid=18416] ppid=18405 vsize=32744 CPUtime=1.59 /proc/18416/stat : 18416 (cudf2lp) R 18405 18405 2160 34817 2160 4202496 10520 0 15 0 156 3 0 0 25 0 1 0 59532308 33529856 7988 1283457024 134512640 135786343 4287540720 18446744073709551615 134571611 0 0 6 0 0 0 0 17 0 0 0 0 /proc/18416/statm: 8186 7988 139 311 0 7873 0 Current children cumulated CPU time (s) 2.89 Current children cumulated vsize (KiB) 92768 [startup+6.31038 s] /proc/loadavg: 1.08 1.04 1.01 2/36 18416 /proc/meminfo: memFree=795580/1048576 swapFree=0/0 [pid=18405] ppid=18404 vsize=2596 CPUtime=5.11 /proc/18405/stat : 18405 (aspuncud-user-1) S 18404 18405 2160 34817 2160 4202496 573 45365 0 41 0 0 486 25 18 0 1 0 59532303 2658304 298 1283457024 134512640 135304128 4292421472 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18405/statm: 649 298 251 194 0 36 0 [pid=18414] ppid=18405 vsize=83136 CPUtime=0.98 /proc/18414/stat : 18414 (unclasp) R 18405 18405 2160 34817 2160 4202496 23961 0 7 0 88 10 0 0 18 0 1 0 59532308 85131264 19903 1283457024 134512640 135121179 4290009952 18446744073709551615 4157533060 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/18414/statm: 20784 19903 318 149 0 19975 0 Current children cumulated CPU time (s) 6.09 Current children cumulated vsize (KiB) 85732 [startup+12.712 s] /proc/loadavg: 1.07 1.04 1.00 2/35 18416 /proc/meminfo: memFree=861572/1048576 swapFree=0/0 [pid=18405] ppid=18404 vsize=2596 CPUtime=5.11 /proc/18405/stat : 18405 (aspuncud-user-1) S 18404 18405 2160 34817 2160 4202496 573 45365 0 41 0 0 486 25 18 0 1 0 59532303 2658304 298 1283457024 134512640 135304128 4292421472 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18405/statm: 649 298 251 194 0 36 0 [pid=18414] ppid=18405 vsize=87820 CPUtime=7.38 /proc/18414/stat : 18414 (unclasp) R 18405 18405 2160 34817 2160 4202496 128455 0 7 0 691 47 0 0 25 0 1 0 59532308 89927680 20218 1283457024 134512640 135121179 4290009952 18446744073709551615 134734464 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/18414/statm: 21955 20218 319 149 0 21146 0 Current children cumulated CPU time (s) 12.49 Current children cumulated vsize (KiB) 90416 [startup+25.5061 s] /proc/loadavg: 1.06 1.04 1.00 2/35 18416 /proc/meminfo: memFree=861696/1048576 swapFree=0/0 [pid=18405] ppid=18404 vsize=2596 CPUtime=5.11 /proc/18405/stat : 18405 (aspuncud-user-1) S 18404 18405 2160 34817 2160 4202496 573 45365 0 41 0 0 486 25 18 0 1 0 59532303 2658304 298 1283457024 134512640 135304128 4292421472 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18405/statm: 649 298 251 194 0 36 0 [pid=18414] ppid=18405 vsize=87364 CPUtime=20.16 /proc/18414/stat : 18414 (unclasp) R 18405 18405 2160 34817 2160 4202496 332301 0 7 0 1876 140 0 0 25 0 1 0 59532308 89460736 20081 1283457024 134512640 135121179 4290009952 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/18414/statm: 21841 20081 319 149 0 21032 0 Current children cumulated CPU time (s) 25.27 Current children cumulated vsize (KiB) 89960 [startup+51.1069 s] /proc/loadavg: 1.11 1.05 1.01 2/35 18416 /proc/meminfo: memFree=859712/1048576 swapFree=0/0 [pid=18405] ppid=18404 vsize=2596 CPUtime=5.11 /proc/18405/stat : 18405 (aspuncud-user-1) S 18404 18405 2160 34817 2160 4202496 573 45365 0 41 0 0 486 25 18 0 1 0 59532303 2658304 298 1283457024 134512640 135304128 4292421472 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18405/statm: 649 298 251 194 0 36 0 [pid=18414] ppid=18405 vsize=87372 CPUtime=45.77 /proc/18414/stat : 18414 (unclasp) R 18405 18405 2160 34817 2160 4202496 732543 0 7 0 4266 311 0 0 25 0 1 0 59532308 89468928 20101 1283457024 134512640 135121179 4290009952 18446744073709551615 134734368 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/18414/statm: 21843 20101 321 149 0 21034 0 Current children cumulated CPU time (s) 50.88 Current children cumulated vsize (KiB) 89968 [startup+102.307 s] /proc/loadavg: 1.05 1.04 1.00 2/35 18416 /proc/meminfo: memFree=859588/1048576 swapFree=0/0 [pid=18405] ppid=18404 vsize=2596 CPUtime=5.11 /proc/18405/stat : 18405 (aspuncud-user-1) S 18404 18405 2160 34817 2160 4202496 573 45365 0 41 0 0 486 25 18 0 1 0 59532303 2658304 298 1283457024 134512640 135304128 4292421472 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18405/statm: 649 298 251 194 0 36 0 [pid=18414] ppid=18405 vsize=87384 CPUtime=96.93 /proc/18414/stat : 18414 (unclasp) R 18405 18405 2160 34817 2160 4202496 1506428 0 7 0 9049 644 0 0 25 0 1 0 59532308 89481216 20127 1283457024 134512640 135121179 4290009952 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/18414/statm: 21846 20127 321 149 0 21037 0 Current children cumulated CPU time (s) 102.04 Current children cumulated vsize (KiB) 89980 [startup+162.311 s] /proc/loadavg: 1.02 1.03 1.00 2/37 18422 /proc/meminfo: memFree=857704/1048576 swapFree=0/0 [pid=18405] ppid=18404 vsize=2596 CPUtime=5.11 /proc/18405/stat : 18405 (aspuncud-user-1) S 18404 18405 2160 34817 2160 4202496 573 45365 0 41 0 0 486 25 18 0 1 0 59532303 2658304 298 1283457024 134512640 135304128 4292421472 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18405/statm: 649 298 251 194 0 36 0 [pid=18414] ppid=18405 vsize=88116 CPUtime=156.86 /proc/18414/stat : 18414 (unclasp) R 18405 18405 2160 34817 2160 4202496 2347584 0 7 0 14661 1025 0 0 25 0 1 0 59532308 90230784 20372 1283457024 134512640 135121179 4290009952 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/18414/statm: 22029 20372 321 149 0 21220 0 Current children cumulated CPU time (s) 161.97 Current children cumulated vsize (KiB) 90712 [startup+222.314 s] /proc/loadavg: 1.00 1.02 1.00 2/36 18427 /proc/meminfo: memFree=858216/1048576 swapFree=0/0 [pid=18405] ppid=18404 vsize=2596 CPUtime=5.11 /proc/18405/stat : 18405 (aspuncud-user-1) S 18404 18405 2160 34817 2160 4202496 573 45365 0 41 0 0 486 25 18 0 1 0 59532303 2658304 298 1283457024 134512640 135304128 4292421472 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18405/statm: 649 298 251 194 0 36 0 [pid=18414] ppid=18405 vsize=90184 CPUtime=216.81 /proc/18414/stat : 18414 (unclasp) R 18405 18405 2160 34817 2160 4202496 3128796 0 7 0 20306 1375 0 0 25 0 1 0 59532308 92348416 20838 1283457024 134512640 135121179 4290009952 18446744073709551615 134990465 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/18414/statm: 22546 20838 321 149 0 21737 0 Current children cumulated CPU time (s) 221.92 Current children cumulated vsize (KiB) 92780 [startup+282.313 s] /proc/loadavg: 1.00 1.02 1.00 2/36 18427 /proc/meminfo: memFree=859456/1048576 swapFree=0/0 [pid=18405] ppid=18404 vsize=2596 CPUtime=5.11 /proc/18405/stat : 18405 (aspuncud-user-1) S 18404 18405 2160 34817 2160 4202496 573 45365 0 41 0 0 486 25 18 0 1 0 59532303 2658304 298 1283457024 134512640 135304128 4292421472 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18405/statm: 649 298 251 194 0 36 0 [pid=18414] ppid=18405 vsize=88132 CPUtime=276.77 /proc/18414/stat : 18414 (unclasp) R 18405 18405 2160 34817 2160 4202496 3896055 0 7 0 25953 1724 0 0 25 0 1 0 59532308 90247168 20424 1283457024 134512640 135121179 4290009952 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/18414/statm: 22033 20424 321 149 0 21224 0 Current children cumulated CPU time (s) 281.88 Current children cumulated vsize (KiB) 90728 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.506 s] /proc/loadavg: 1.00 1.02 1.00 2/35 18427 /proc/meminfo: memFree=859464/1048576 swapFree=0/0 [pid=18405] ppid=18404 vsize=2596 CPUtime=5.11 /proc/18405/stat : 18405 (aspuncud-user-1) S 18404 18405 2160 34817 2160 4202496 573 45365 0 41 0 0 486 25 18 0 1 0 59532303 2658304 298 1283457024 134512640 135304128 4292421472 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18405/statm: 649 298 251 194 0 36 0 [pid=18414] ppid=18405 vsize=88132 CPUtime=284.96 /proc/18414/stat : 18414 (unclasp) R 18405 18405 2160 34817 2160 4202496 3999507 0 7 0 26726 1770 0 0 25 0 1 0 59532308 90247168 20426 1283457024 134512640 135121179 4290009952 18446744073709551615 4159087685 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/18414/statm: 22033 20426 321 149 0 21224 0 Current children cumulated CPU time (s) 290.07 Current children cumulated vsize (KiB) 90728 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.506 s] /proc/loadavg: 1.00 1.02 1.00 2/35 18427 /proc/meminfo: memFree=859464/1048576 swapFree=0/0 [pid=18405] ppid=18404 vsize=2596 CPUtime=5.11 /proc/18405/stat : 18405 (aspuncud-user-1) S 18404 18405 2160 34817 2160 4202496 573 45365 0 41 0 0 486 25 18 0 1 0 59532303 2658304 298 1283457024 134512640 135304128 4292421472 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18405/statm: 649 298 251 194 0 36 0 [pid=18414] ppid=18405 vsize=88132 CPUtime=284.96 /proc/18414/stat : 18414 (unclasp) R 18405 18405 2160 34817 2160 4202496 3999507 0 7 0 26726 1770 0 0 25 0 1 0 59532308 90247168 20426 1283457024 134512640 135121179 4290009952 18446744073709551615 4159087685 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/18414/statm: 22033 20426 321 149 0 21224 0 Current children cumulated CPU time (s) 290.07 Current children cumulated vsize (KiB) 90728 Child status: 0 Real time (s): 290.546 CPU time (s): 290.09 CPU user time (s): 272.133 CPU system time (s): 17.9571 CPU usage (%): 99.843 Max. virtual memory (cumulated for all children) (KiB): 181060 getrusage(RUSAGE_CHILDREN,...) data: user time used= 272.133 system time used= 17.9571 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 4047836 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= 5918 involuntary context switches= 8159 runsolver used 0.004 second user time and 0 second system time The end