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/rand455.cudf.dudf-random.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-random//rand455.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/rand455.cudf.dudf-random.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.02 1.00 1/38 6417 /proc/meminfo: memFree=944652/1048576 swapFree=0/0 [pid=6417] ppid=6416 vsize=3020 CPUtime=0 /proc/6417/stat : 6417 (runsolver) D 6416 6417 2160 34817 2160 4202560 73 0 0 0 0 0 0 0 25 0 1 0 53167462 3092480 94 1283457024 134512640 134586868 4293613568 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/6417/statm: 755 94 62 19 0 54 0 [startup+0.159834 s] /proc/loadavg: 1.00 1.02 1.00 1/38 6417 /proc/meminfo: memFree=944652/1048576 swapFree=0/0 [pid=6417] ppid=6416 vsize=2596 CPUtime=0 /proc/6417/stat : 6417 (aspuncud-user-1) S 6416 6417 2160 34817 2160 4202496 574 1516 0 3 0 0 0 0 25 0 1 0 53167462 2658304 298 1283457024 134512640 135304128 4290446768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6417/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.217796 s] /proc/loadavg: 1.00 1.02 1.00 1/38 6417 /proc/meminfo: memFree=944652/1048576 swapFree=0/0 [pid=6417] ppid=6416 vsize=2596 CPUtime=0 /proc/6417/stat : 6417 (aspuncud-user-1) S 6416 6417 2160 34817 2160 4202496 574 1516 0 3 0 0 0 0 25 0 1 0 53167462 2658304 298 1283457024 134512640 135304128 4290446768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6417/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.307829 s] /proc/loadavg: 1.00 1.02 1.00 1/38 6417 /proc/meminfo: memFree=944652/1048576 swapFree=0/0 [pid=6417] ppid=6416 vsize=2596 CPUtime=0 /proc/6417/stat : 6417 (aspuncud-user-1) S 6416 6417 2160 34817 2160 4202496 574 1516 0 3 0 0 0 0 25 0 1 0 53167462 2658304 298 1283457024 134512640 135304128 4290446768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6417/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.707888 s] /proc/loadavg: 1.00 1.02 1.00 1/38 6417 /proc/meminfo: memFree=944652/1048576 swapFree=0/0 [pid=6417] ppid=6416 vsize=2596 CPUtime=0 /proc/6417/stat : 6417 (aspuncud-user-1) S 6416 6417 2160 34817 2160 4202496 574 1516 0 3 0 0 0 0 25 0 1 0 53167462 2658304 298 1283457024 134512640 135304128 4290446768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6417/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50811 s] /proc/loadavg: 1.00 1.02 1.00 2/42 6428 /proc/meminfo: memFree=926124/1048576 swapFree=0/0 [pid=6417] ppid=6416 vsize=2596 CPUtime=0 /proc/6417/stat : 6417 (aspuncud-user-1) S 6416 6417 2160 34817 2160 4202496 574 1516 0 3 0 0 0 0 25 0 1 0 53167462 2658304 298 1283457024 134512640 135304128 4290446768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6417/statm: 649 298 251 194 0 36 0 [pid=6426] ppid=6417 vsize=3980 CPUtime=0 /proc/6426/stat : 6426 (unclasp) S 6417 6417 2160 34817 2160 4202496 563 0 6 0 0 0 0 0 18 0 1 0 53167467 4075520 433 1283457024 134512640 135121179 4294930400 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/6426/statm: 995 433 275 149 0 186 0 [pid=6427] ppid=6417 vsize=3592 CPUtime=0.04 /proc/6427/stat : 6427 (gringo) R 6417 6417 2160 34817 2160 4202496 595 0 23 0 4 0 0 0 18 0 1 0 53167467 3678208 457 1283457024 134512640 137056543 4294925440 18446744073709551615 136099637 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6427/statm: 898 457 253 622 0 273 0 [pid=6428] ppid=6417 vsize=26524 CPUtime=1.25 /proc/6428/stat : 6428 (cudf2lp) R 6417 6417 2160 34817 2160 4202496 8639 0 15 0 124 1 0 0 25 0 1 0 53167467 27160576 6414 1283457024 134512640 135786343 4289187488 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/6428/statm: 6631 6414 139 311 0 6318 0 Current children cumulated CPU time (s) 1.29 Current children cumulated vsize (KiB) 36692 [startup+3.10846 s] /proc/loadavg: 1.00 1.02 1.00 2/42 6428 /proc/meminfo: memFree=891716/1048576 swapFree=0/0 [pid=6417] ppid=6416 vsize=2596 CPUtime=0 /proc/6417/stat : 6417 (aspuncud-user-1) S 6416 6417 2160 34817 2160 4202496 574 1516 0 3 0 0 0 0 25 0 1 0 53167462 2658304 298 1283457024 134512640 135304128 4290446768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6417/statm: 649 298 251 194 0 36 0 [pid=6426] ppid=6417 vsize=25988 CPUtime=0.09 /proc/6426/stat : 6426 (unclasp) S 6417 6417 2160 34817 2160 4202496 7043 0 6 0 9 0 0 0 18 0 1 0 53167467 26611712 5849 1283457024 134512640 135121179 4294930400 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/6426/statm: 6497 5849 275 149 0 5688 0 [pid=6427] ppid=6417 vsize=36420 CPUtime=1.29 /proc/6427/stat : 6427 (gringo) R 6417 6417 2160 34817 2160 4202496 11249 0 23 0 126 3 0 0 18 0 1 0 53167467 37294080 7114 1283457024 134512640 137056543 4294925440 18446744073709551615 134548130 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6427/statm: 9105 7114 253 622 0 8480 0 [pid=6428] ppid=6417 vsize=26524 CPUtime=1.5 /proc/6428/stat : 6428 (cudf2lp) R 6417 6417 2160 34817 2160 4202496 8639 0 15 0 148 2 0 0 25 0 1 0 53167467 27160576 6414 1283457024 134512640 135786343 4289187488 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/6428/statm: 6631 6414 139 311 0 6318 0 Current children cumulated CPU time (s) 2.88 Current children cumulated vsize (KiB) 91528 [startup+6.30979 s] /proc/loadavg: 1.08 1.03 1.01 2/40 6429 /proc/meminfo: memFree=878604/1048576 swapFree=0/0 [pid=6417] ppid=6416 vsize=2596 CPUtime=4.18 /proc/6417/stat : 6417 (aspuncud-user-1) S 6416 6417 2160 34817 2160 4202496 574 37574 0 41 0 0 402 16 18 0 1 0 53167462 2658304 298 1283457024 134512640 135304128 4290446768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6417/statm: 649 298 251 194 0 36 0 [pid=6426] ppid=6417 vsize=66152 CPUtime=1.88 /proc/6426/stat : 6426 (unclasp) R 6417 6417 2160 34817 2160 4202496 29691 0 7 0 180 8 0 0 20 0 1 0 53167467 67739648 15139 1283457024 134512640 135121179 4294930400 18446744073709551615 134734410 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6426/statm: 16538 15139 319 149 0 15729 0 Current children cumulated CPU time (s) 6.06 Current children cumulated vsize (KiB) 68748 [startup+12.712 s] /proc/loadavg: 1.07 1.03 1.00 2/40 6429 /proc/meminfo: memFree=879976/1048576 swapFree=0/0 [pid=6417] ppid=6416 vsize=2596 CPUtime=4.18 /proc/6417/stat : 6417 (aspuncud-user-1) S 6416 6417 2160 34817 2160 4202496 574 37574 0 41 0 0 402 16 18 0 1 0 53167462 2658304 298 1283457024 134512640 135304128 4290446768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6417/statm: 649 298 251 194 0 36 0 [pid=6426] ppid=6417 vsize=67192 CPUtime=8.29 /proc/6426/stat : 6426 (unclasp) R 6417 6417 2160 34817 2160 4202496 109867 0 7 0 785 44 0 0 25 0 1 0 53167467 68804608 15329 1283457024 134512640 135121179 4294930400 18446744073709551615 134990474 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6426/statm: 16798 15329 319 149 0 15989 0 Current children cumulated CPU time (s) 12.47 Current children cumulated vsize (KiB) 69788 [startup+25.5066 s] /proc/loadavg: 1.06 1.03 1.00 2/40 6431 /proc/meminfo: memFree=879604/1048576 swapFree=0/0 [pid=6417] ppid=6416 vsize=2596 CPUtime=4.18 /proc/6417/stat : 6417 (aspuncud-user-1) S 6416 6417 2160 34817 2160 4202496 574 37574 0 41 0 0 402 16 18 0 1 0 53167462 2658304 298 1283457024 134512640 135304128 4290446768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6417/statm: 649 298 251 194 0 36 0 [pid=6426] ppid=6417 vsize=67560 CPUtime=21.07 /proc/6426/stat : 6426 (unclasp) R 6417 6417 2160 34817 2160 4202496 288375 0 7 0 1989 118 0 0 25 0 1 0 53167467 69181440 15504 1283457024 134512640 135121179 4294930400 18446744073709551615 134981897 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6426/statm: 16890 15504 321 149 0 16081 0 Current children cumulated CPU time (s) 25.25 Current children cumulated vsize (KiB) 70156 [startup+51.1068 s] /proc/loadavg: 1.04 1.03 1.00 2/40 6433 /proc/meminfo: memFree=880224/1048576 swapFree=0/0 [pid=6417] ppid=6416 vsize=2596 CPUtime=4.18 /proc/6417/stat : 6417 (aspuncud-user-1) S 6416 6417 2160 34817 2160 4202496 574 37574 0 41 0 0 402 16 18 0 1 0 53167462 2658304 298 1283457024 134512640 135304128 4290446768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6417/statm: 649 298 251 194 0 36 0 [pid=6426] ppid=6417 vsize=67312 CPUtime=46.64 /proc/6426/stat : 6426 (unclasp) R 6417 6417 2160 34817 2160 4202496 631075 0 7 0 4393 271 0 0 25 0 1 0 53167467 68927488 15483 1283457024 134512640 135121179 4294930400 18446744073709551615 134983096 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6426/statm: 16828 15483 321 149 0 16019 0 Current children cumulated CPU time (s) 50.82 Current children cumulated vsize (KiB) 69908 [startup+102.316 s] /proc/loadavg: 1.01 1.02 1.00 2/39 6436 /proc/meminfo: memFree=879992/1048576 swapFree=0/0 [pid=6417] ppid=6416 vsize=2596 CPUtime=4.18 /proc/6417/stat : 6417 (aspuncud-user-1) S 6416 6417 2160 34817 2160 4202496 574 37574 0 41 0 0 402 16 18 0 1 0 53167462 2658304 298 1283457024 134512640 135304128 4290446768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6417/statm: 649 298 251 194 0 36 0 [pid=6426] ppid=6417 vsize=66028 CPUtime=97.79 /proc/6426/stat : 6426 (unclasp) R 6417 6417 2160 34817 2160 4202496 1288959 0 7 0 9228 551 0 0 25 0 1 0 53167467 67612672 15188 1283457024 134512640 135121179 4294930400 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6426/statm: 16507 15188 321 149 0 15698 0 Current children cumulated CPU time (s) 101.97 Current children cumulated vsize (KiB) 68624 [startup+162.308 s] /proc/loadavg: 1.00 1.02 1.00 2/38 6436 /proc/meminfo: memFree=880248/1048576 swapFree=0/0 [pid=6417] ppid=6416 vsize=2596 CPUtime=4.18 /proc/6417/stat : 6417 (aspuncud-user-1) S 6416 6417 2160 34817 2160 4202496 574 37574 0 41 0 0 402 16 18 0 1 0 53167462 2658304 298 1283457024 134512640 135304128 4290446768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6417/statm: 649 298 251 194 0 36 0 [pid=6426] ppid=6417 vsize=65680 CPUtime=157.75 /proc/6426/stat : 6426 (unclasp) R 6417 6417 2160 34817 2160 4202496 2036049 0 7 0 14885 890 0 0 25 0 1 0 53167467 67256320 15086 1283457024 134512640 135121179 4294930400 18446744073709551615 134891399 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6426/statm: 16420 15086 321 149 0 15611 0 Current children cumulated CPU time (s) 161.93 Current children cumulated vsize (KiB) 68276 [startup+222.307 s] /proc/loadavg: 1.00 1.01 1.00 2/38 6437 /proc/meminfo: memFree=878416/1048576 swapFree=0/0 [pid=6417] ppid=6416 vsize=2596 CPUtime=4.18 /proc/6417/stat : 6417 (aspuncud-user-1) S 6416 6417 2160 34817 2160 4202496 574 37574 0 41 0 0 402 16 18 0 1 0 53167462 2658304 298 1283457024 134512640 135304128 4290446768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6417/statm: 649 298 251 194 0 36 0 [pid=6426] ppid=6417 vsize=67184 CPUtime=217.63 /proc/6426/stat : 6426 (unclasp) R 6417 6417 2160 34817 2160 4202496 2777790 0 7 0 20532 1231 0 0 25 0 1 0 53167467 68796416 15546 1283457024 134512640 135121179 4294930400 18446744073709551615 4157479702 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6426/statm: 16796 15546 321 149 0 15987 0 Current children cumulated CPU time (s) 221.81 Current children cumulated vsize (KiB) 69780 [startup+282.308 s] /proc/loadavg: 1.00 1.00 1.00 2/38 6437 /proc/meminfo: memFree=875812/1048576 swapFree=0/0 [pid=6417] ppid=6416 vsize=2596 CPUtime=4.18 /proc/6417/stat : 6417 (aspuncud-user-1) S 6416 6417 2160 34817 2160 4202496 574 37574 0 41 0 0 402 16 18 0 1 0 53167462 2658304 298 1283457024 134512640 135304128 4290446768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6417/statm: 649 298 251 194 0 36 0 [pid=6426] ppid=6417 vsize=67084 CPUtime=277.61 /proc/6426/stat : 6426 (unclasp) R 6417 6417 2160 34817 2160 4202496 3579464 0 7 0 26229 1532 0 0 25 0 1 0 53167467 68694016 15514 1283457024 134512640 135121179 4294930400 18446744073709551615 134734310 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6426/statm: 16771 15514 321 149 0 15962 0 Current children cumulated CPU time (s) 281.79 Current children cumulated vsize (KiB) 69680 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.612 s] /proc/loadavg: 1.00 1.00 1.00 2/38 6437 /proc/meminfo: memFree=876804/1048576 swapFree=0/0 [pid=6417] ppid=6416 vsize=2596 CPUtime=4.18 /proc/6417/stat : 6417 (aspuncud-user-1) S 6416 6417 2160 34817 2160 4202496 574 37574 0 41 0 0 402 16 18 0 1 0 53167462 2658304 298 1283457024 134512640 135304128 4290446768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6417/statm: 649 298 251 194 0 36 0 [pid=6426] ppid=6417 vsize=67748 CPUtime=285.91 /proc/6426/stat : 6426 (unclasp) R 6417 6417 2160 34817 2160 4202496 3684911 0 7 0 27013 1578 0 0 25 0 1 0 53167467 69373952 15678 1283457024 134512640 135121179 4294930400 18446744073709551615 134980996 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6426/statm: 16937 15678 321 149 0 16128 0 Current children cumulated CPU time (s) 290.09 Current children cumulated vsize (KiB) 70344 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.612 s] /proc/loadavg: 1.00 1.00 1.00 2/38 6437 /proc/meminfo: memFree=876804/1048576 swapFree=0/0 [pid=6417] ppid=6416 vsize=2596 CPUtime=4.18 /proc/6417/stat : 6417 (aspuncud-user-1) S 6416 6417 2160 34817 2160 4202496 574 37574 0 41 0 0 402 16 18 0 1 0 53167462 2658304 298 1283457024 134512640 135304128 4290446768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6417/statm: 649 298 251 194 0 36 0 [pid=6426] ppid=6417 vsize=67748 CPUtime=285.91 /proc/6426/stat : 6426 (unclasp) R 6417 6417 2160 34817 2160 4202496 3684911 0 7 0 27013 1578 0 0 25 0 1 0 53167467 69373952 15678 1283457024 134512640 135121179 4294930400 18446744073709551615 134980996 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6426/statm: 16937 15678 321 149 0 16128 0 Current children cumulated CPU time (s) 290.09 Current children cumulated vsize (KiB) 70344 Child status: 0 Real time (s): 290.707 CPU time (s): 290.126 CPU user time (s): 274.161 CPU system time (s): 15.965 CPU usage (%): 99.8003 Max. virtual memory (cumulated for all children) (KiB): 150416 getrusage(RUSAGE_CHILDREN,...) data: user time used= 274.161 system time used= 15.965 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 3725453 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= 4307 involuntary context switches= 6997 runsolver used 0 second user time and 0 second system time The end