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/201108311143/aspuncud-user-1.0/rand461.cudf.dudf-random.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-random//rand461.cudf /home/misc2010/tmp/201108311143/aspuncud-user-1.0/rand461.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.01 1.03 1.00 5/38 24710 /proc/meminfo: memFree=525276/1048576 swapFree=0/0 [pid=24709] ppid=24708 vsize=2584 CPUtime=0 /proc/24709/stat : 24709 (aspuncud-user-1) R 24708 24709 19908 34817 19908 4202496 365 0 0 0 0 0 0 0 25 0 1 0 63086132 2646016 279 1283457024 134512640 135304128 4294246736 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/24709/statm: 646 279 234 194 0 33 0 [pid=24710] ppid=24709 vsize=2584 CPUtime=0 /proc/24710/stat : 24710 (aspuncud-user-1) R 24709 24709 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 63086132 2646016 45 1283457024 134512640 135304128 4294246736 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/24710/statm: 646 45 0 194 0 33 0 [startup+0.124852 s] /proc/loadavg: 1.01 1.03 1.00 5/38 24710 /proc/meminfo: memFree=525276/1048576 swapFree=0/0 [pid=24709] ppid=24708 vsize=2588 CPUtime=0 /proc/24709/stat : 24709 (aspuncud-user-1) S 24708 24709 19908 34817 19908 4202496 577 1520 0 0 0 0 0 0 25 0 1 0 63086132 2650112 297 1283457024 134512640 135304128 4294246736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24709/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+0.204869 s] /proc/loadavg: 1.01 1.03 1.00 5/38 24710 /proc/meminfo: memFree=525276/1048576 swapFree=0/0 [pid=24709] ppid=24708 vsize=2588 CPUtime=0 /proc/24709/stat : 24709 (aspuncud-user-1) S 24708 24709 19908 34817 19908 4202496 577 1520 0 0 0 0 0 0 25 0 1 0 63086132 2650112 297 1283457024 134512640 135304128 4294246736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24709/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+0.304885 s] /proc/loadavg: 1.01 1.03 1.00 5/38 24710 /proc/meminfo: memFree=525276/1048576 swapFree=0/0 [pid=24709] ppid=24708 vsize=2588 CPUtime=0 /proc/24709/stat : 24709 (aspuncud-user-1) S 24708 24709 19908 34817 19908 4202496 577 1520 0 0 0 0 0 0 25 0 1 0 63086132 2650112 297 1283457024 134512640 135304128 4294246736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24709/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+0.704956 s] /proc/loadavg: 1.01 1.03 1.00 5/38 24710 /proc/meminfo: memFree=525276/1048576 swapFree=0/0 [pid=24709] ppid=24708 vsize=2588 CPUtime=0 /proc/24709/stat : 24709 (aspuncud-user-1) S 24708 24709 19908 34817 19908 4202496 577 1520 0 0 0 0 0 0 25 0 1 0 63086132 2650112 297 1283457024 134512640 135304128 4294246736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24709/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+1.50511 s] /proc/loadavg: 1.01 1.03 1.00 2/41 24720 /proc/meminfo: memFree=501044/1048576 swapFree=0/0 [pid=24709] ppid=24708 vsize=2588 CPUtime=0 /proc/24709/stat : 24709 (aspuncud-user-1) S 24708 24709 19908 34817 19908 4202496 577 1520 0 0 0 0 0 0 25 0 1 0 63086132 2650112 297 1283457024 134512640 135304128 4294246736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24709/statm: 647 297 251 194 0 34 0 [pid=24718] ppid=24709 vsize=3448 CPUtime=0 /proc/24718/stat : 24718 (unclasp) S 24709 24709 19908 34817 19908 4202496 407 0 0 0 0 0 0 0 25 0 1 0 63086133 3530752 272 1283457024 134512640 135121179 4290848384 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/24718/statm: 862 272 240 149 0 53 0 [pid=24719] ppid=24709 vsize=2696 CPUtime=0 /proc/24719/stat : 24719 (gringo) S 24709 24709 19908 34817 19908 4202496 408 0 0 0 0 0 0 0 25 0 1 0 63086133 2760704 281 1283457024 134512640 137056543 4286909008 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/24719/statm: 674 281 252 622 0 49 0 [pid=24720] ppid=24709 vsize=27488 CPUtime=1.49 /proc/24720/stat : 24720 (cudf2lp) R 24709 24709 19908 34817 19908 4202496 7717 0 0 0 144 5 0 0 25 0 1 0 63086133 28147712 6221 1283457024 134512640 135786343 4290778736 18446744073709551615 134614669 0 0 6 0 0 0 0 17 0 0 0 0 /proc/24720/statm: 6872 6221 128 311 0 6559 0 Current children cumulated CPU time (s) 1.49 Current children cumulated vsize (KiB) 36220 [startup+3.10554 s] /proc/loadavg: 1.01 1.03 1.00 2/41 24720 /proc/meminfo: memFree=481824/1048576 swapFree=0/0 [pid=24709] ppid=24708 vsize=2588 CPUtime=2.37 /proc/24709/stat : 24709 (aspuncud-user-1) R 24708 24709 19908 34817 19908 4202496 578 15021 0 0 0 0 227 10 19 0 1 0 63086132 2650112 297 1283457024 134512640 135304128 4294246736 18446744073709551615 4294960130 0 65536 4 1132560123 0 0 0 17 0 0 0 0 /proc/24709/statm: 647 297 251 194 0 34 0 [pid=24718] ppid=24709 vsize=7692 CPUtime=0.63 /proc/24718/stat : 24718 (unclasp) R 24709 24709 19908 34817 19908 4202496 1669 0 0 0 63 0 0 0 18 0 1 0 63086133 7876608 1404 1283457024 134512640 135121179 4290848384 18446744073709551615 134981270 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/24718/statm: 1923 1404 323 149 0 1114 0 [pid=24719] ppid=24709 vsize=0 CPUtime=0.09 /proc/24719/stat : 24719 (gringo) Z 24709 24709 19908 34817 19908 4202508 1220 0 0 0 9 0 0 0 18 0 1 0 63086133 0 0 1283457024 0 0 0 0 0 0 0 6 16384 18446744071564254338 0 0 17 0 0 0 0 /proc/24719/statm: 0 0 0 0 0 0 0 Current children cumulated CPU time (s) 3.09 Current children cumulated vsize (KiB) 10280 [startup+6.30646 s] /proc/loadavg: 1.09 1.04 1.01 2/39 24720 /proc/meminfo: memFree=507904/1048576 swapFree=0/0 [pid=24709] ppid=24708 vsize=2588 CPUtime=2.46 /proc/24709/stat : 24709 (aspuncud-user-1) S 24708 24709 19908 34817 19908 4202496 578 16241 0 0 0 0 236 10 17 0 1 0 63086132 2650112 297 1283457024 134512640 135304128 4294246736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24709/statm: 647 297 251 194 0 34 0 [pid=24718] ppid=24709 vsize=24224 CPUtime=3.82 /proc/24718/stat : 24718 (unclasp) R 24709 24709 19908 34817 19908 4202496 6025 0 0 0 381 1 0 0 25 0 1 0 63086133 24805376 5470 1283457024 134512640 135121179 4290848384 18446744073709551615 134873584 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/24718/statm: 6056 5470 323 149 0 5247 0 Current children cumulated CPU time (s) 6.28 Current children cumulated vsize (KiB) 26812 [startup+12.7086 s] /proc/loadavg: 1.08 1.04 1.00 2/39 24720 /proc/meminfo: memFree=481244/1048576 swapFree=0/0 [pid=24709] ppid=24708 vsize=2588 CPUtime=2.46 /proc/24709/stat : 24709 (aspuncud-user-1) S 24708 24709 19908 34817 19908 4202496 578 16241 0 0 0 0 236 10 17 0 1 0 63086132 2650112 297 1283457024 134512640 135304128 4294246736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24709/statm: 647 297 251 194 0 34 0 [pid=24718] ppid=24709 vsize=50740 CPUtime=10.21 /proc/24718/stat : 24718 (unclasp) R 24709 24709 19908 34817 19908 4202496 12863 0 0 0 1017 4 0 0 25 0 1 0 63086133 51957760 12046 1283457024 134512640 135121179 4290848384 18446744073709551615 134839162 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/24718/statm: 12685 12046 323 149 0 11876 0 Current children cumulated CPU time (s) 12.67 Current children cumulated vsize (KiB) 53328 [startup+25.5027 s] /proc/loadavg: 1.06 1.04 1.00 2/39 24720 /proc/meminfo: memFree=420980/1048576 swapFree=0/0 [pid=24709] ppid=24708 vsize=2588 CPUtime=2.46 /proc/24709/stat : 24709 (aspuncud-user-1) S 24708 24709 19908 34817 19908 4202496 578 16241 0 0 0 0 236 10 17 0 1 0 63086132 2650112 297 1283457024 134512640 135304128 4294246736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24709/statm: 647 297 251 194 0 34 0 [pid=24718] ppid=24709 vsize=108856 CPUtime=22.99 /proc/24718/stat : 24718 (unclasp) R 24709 24709 19908 34817 19908 4202496 28037 0 0 0 2291 8 0 0 25 0 1 0 63086133 111468544 26512 1283457024 134512640 135121179 4290848384 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/24718/statm: 27214 26512 323 149 0 26405 0 Current children cumulated CPU time (s) 25.45 Current children cumulated vsize (KiB) 111444 [startup+51.1113 s] /proc/loadavg: 1.04 1.03 1.00 2/38 24720 /proc/meminfo: memFree=299964/1048576 swapFree=0/0 [pid=24709] ppid=24708 vsize=2588 CPUtime=2.46 /proc/24709/stat : 24709 (aspuncud-user-1) S 24708 24709 19908 34817 19908 4202496 578 16241 0 0 0 0 236 10 17 0 1 0 63086132 2650112 297 1283457024 134512640 135304128 4294246736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24709/statm: 647 297 251 194 0 34 0 [pid=24718] ppid=24709 vsize=230724 CPUtime=48.58 /proc/24718/stat : 24718 (unclasp) R 24709 24709 19908 34817 19908 4202496 60542 0 0 0 4842 16 0 0 25 0 1 0 63086133 236261376 57040 1283457024 134512640 135121179 4290848384 18446744073709551615 134839096 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/24718/statm: 57681 57040 323 149 0 56872 0 Current children cumulated CPU time (s) 51.04 Current children cumulated vsize (KiB) 233312 [startup+102.309 s] /proc/loadavg: 1.02 1.03 1.00 2/38 24720 /proc/meminfo: memFree=144220/1048576 swapFree=0/0 [pid=24709] ppid=24708 vsize=2588 CPUtime=2.46 /proc/24709/stat : 24709 (aspuncud-user-1) S 24708 24709 19908 34817 19908 4202496 578 16241 0 0 0 0 236 10 17 0 1 0 63086132 2650112 297 1283457024 134512640 135304128 4294246736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24709/statm: 647 297 251 194 0 34 0 [pid=24718] ppid=24709 vsize=384304 CPUtime=99.73 /proc/24718/stat : 24718 (unclasp) R 24709 24709 19908 34817 19908 4202496 134711 0 0 0 9931 42 0 0 25 0 1 0 63086133 393527296 95238 1283457024 134512640 135121179 4290848384 18446744073709551615 134891771 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/24718/statm: 96076 95238 323 149 0 95267 0 Current children cumulated CPU time (s) 102.19 Current children cumulated vsize (KiB) 386892 [startup+162.308 s] /proc/loadavg: 1.00 1.02 1.00 2/38 24720 /proc/meminfo: memFree=5856/1048576 swapFree=0/0 [pid=24709] ppid=24708 vsize=2588 CPUtime=2.46 /proc/24709/stat : 24709 (aspuncud-user-1) S 24708 24709 19908 34817 19908 4202496 578 16241 0 0 0 0 236 10 17 0 1 0 63086132 2650112 297 1283457024 134512640 135304128 4294246736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24709/statm: 647 297 251 194 0 34 0 [pid=24718] ppid=24709 vsize=548396 CPUtime=159.64 /proc/24718/stat : 24718 (unclasp) R 24709 24709 19908 34817 19908 4202496 232879 0 0 0 15876 88 0 0 25 0 1 0 63086133 561557504 136256 1283457024 134512640 135121179 4290848384 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/24718/statm: 137099 136256 323 149 0 136290 0 Current children cumulated CPU time (s) 162.1 Current children cumulated vsize (KiB) 550984 [startup+222.307 s] /proc/loadavg: 1.00 1.01 1.00 2/38 24720 /proc/meminfo: memFree=6380/1048576 swapFree=0/0 [pid=24709] ppid=24708 vsize=2588 CPUtime=2.46 /proc/24709/stat : 24709 (aspuncud-user-1) S 24708 24709 19908 34817 19908 4202496 578 16241 0 0 0 0 236 10 17 0 1 0 63086132 2650112 297 1283457024 134512640 135304128 4294246736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24709/statm: 647 297 251 194 0 34 0 [pid=24718] ppid=24709 vsize=702816 CPUtime=219.57 /proc/24718/stat : 24718 (unclasp) R 24709 24709 19908 34817 19908 4202496 342698 0 0 0 21830 127 0 0 25 0 1 0 63086133 719683584 174381 1283457024 134512640 135121179 4290848384 18446744073709551615 134891843 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/24718/statm: 175704 174381 323 149 0 174895 0 Current children cumulated CPU time (s) 222.03 Current children cumulated vsize (KiB) 705404 [startup+282.307 s] /proc/loadavg: 1.00 1.01 1.00 2/38 24720 /proc/meminfo: memFree=6092/1048576 swapFree=0/0 [pid=24709] ppid=24708 vsize=2588 CPUtime=2.46 /proc/24709/stat : 24709 (aspuncud-user-1) S 24708 24709 19908 34817 19908 4202496 578 16241 0 0 0 0 236 10 17 0 1 0 63086132 2650112 297 1283457024 134512640 135304128 4294246736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24709/statm: 647 297 251 194 0 34 0 [pid=24718] ppid=24709 vsize=867416 CPUtime=279.48 /proc/24718/stat : 24718 (unclasp) R 24709 24709 19908 34817 19908 4202496 466343 0 0 0 27768 180 0 0 25 0 1 0 63086133 888233984 214914 1283457024 134512640 135121179 4290848384 18446744073709551615 134891771 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/24718/statm: 216854 214914 323 149 0 216045 0 Current children cumulated CPU time (s) 281.94 Current children cumulated vsize (KiB) 870004 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.409 s] /proc/loadavg: 1.00 1.01 1.00 2/40 24722 /proc/meminfo: memFree=6088/1048576 swapFree=0/0 [pid=24709] ppid=24708 vsize=2588 CPUtime=2.46 /proc/24709/stat : 24709 (aspuncud-user-1) S 24708 24709 19908 34817 19908 4202496 578 16241 0 0 0 0 236 10 17 0 1 0 63086132 2650112 297 1283457024 134512640 135304128 4294246736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24709/statm: 647 297 251 194 0 34 0 [pid=24718] ppid=24709 vsize=892948 CPUtime=287.56 /proc/24718/stat : 24718 (unclasp) R 24709 24709 19908 34817 19908 4202496 482042 0 0 0 28572 184 0 0 25 0 1 0 63086133 914378752 221288 1283457024 134512640 135121179 4290848384 18446744073709551615 134836023 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/24718/statm: 223237 221288 323 149 0 222428 0 Current children cumulated CPU time (s) 290.02 Current children cumulated vsize (KiB) 895536 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.523 s] /proc/loadavg: 1.00 1.01 1.00 2/40 24722 /proc/meminfo: memFree=6088/1048576 swapFree=0/0 [pid=24709] ppid=24708 vsize=2592 CPUtime=290.09 /proc/24709/stat : 24709 (aspuncud-user-1) S 24708 24709 19908 34817 19908 4202496 638 498776 0 3 0 0 28809 200 20 0 1 0 63086132 2654208 305 1283457024 134512640 135304128 4294246736 18446744073709551615 4294960130 0 65536 16902 1132543225 18446744071564329979 0 0 17 0 0 0 0 /proc/24709/statm: 648 305 258 194 0 35 0 Current children cumulated CPU time (s) 290.09 Current children cumulated vsize (KiB) 2592 Child status: 0 Real time (s): 290.575 CPU time (s): 290.11 CPU user time (s): 288.098 CPU system time (s): 2.01213 CPU usage (%): 99.8402 Max. virtual memory (cumulated for all children) (KiB): 895856 getrusage(RUSAGE_CHILDREN,...) data: user time used= 288.098 system time used= 2.01213 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 501253 page faults= 6 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 206 involuntary context switches= 4043 runsolver used 0 second user time and 0 second system time The end