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/201108291842/aspuncud-user-1.0/rand252.cudf.dudf-random.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-random//rand252.cudf /home/misc2010/tmp/201108291842/aspuncud-user-1.0/rand252.cudf.dudf-random.result -notuptodate,-removed,-changed 

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.14 1.01 0.87 5/39 18524
/proc/meminfo: memFree=776216/1048576 swapFree=0/0
[pid=18521] ppid=18520 vsize=2588 CPUtime=0
/proc/18521/stat : 18521 (aspuncud-user-1) S 18520 18521 17511 34816 17511 4202496 374 0 0 0 0 0 0 0 18 0 1 0 46015367 2650112 280 1283457024 134512640 135304128 4293853424 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/18521/statm: 647 280 234 194 0 34 0
[pid=18522] ppid=18521 vsize=2588 CPUtime=0
/proc/18522/stat : 18522 (aspuncud-user-1) S 18521 18521 17511 34816 17511 4202560 118 0 0 0 0 0 0 0 18 0 1 0 46015367 2650112 134 1283457024 134512640 135304128 4293853424 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/18522/statm: 647 134 87 194 0 34 0
[pid=18523] ppid=18522 vsize=2588 CPUtime=0
/proc/18523/stat : 18523 (aspuncud-user-1) R 18522 18521 17511 34816 17511 4202560 127 0 0 0 0 0 0 0 25 0 1 0 46015367 2650112 151 1283457024 134512640 135304128 4293853424 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/18523/statm: 647 151 104 194 0 34 0
[pid=18524] ppid=18523 vsize=2588 CPUtime=0
/proc/18524/stat : 18524 (aspuncud-user-1) R 18523 18521 17511 34816 17511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 46015367 2650112 47 1283457024 134512640 135304128 4293853424 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/18524/statm: 647 47 0 194 0 34 0

[startup+0.174781 s]
/proc/loadavg: 1.14 1.01 0.87 5/39 18524
/proc/meminfo: memFree=776216/1048576 swapFree=0/0
[pid=18521] ppid=18520 vsize=2592 CPUtime=0
/proc/18521/stat : 18521 (aspuncud-user-1) S 18520 18521 17511 34816 17511 4202496 572 1521 0 0 0 0 0 0 25 0 1 0 46015367 2654208 298 1283457024 134512640 135304128 4293853424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18521/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.204787 s]
/proc/loadavg: 1.14 1.01 0.87 5/39 18524
/proc/meminfo: memFree=776216/1048576 swapFree=0/0
[pid=18521] ppid=18520 vsize=2592 CPUtime=0
/proc/18521/stat : 18521 (aspuncud-user-1) S 18520 18521 17511 34816 17511 4202496 572 1521 0 0 0 0 0 0 25 0 1 0 46015367 2654208 298 1283457024 134512640 135304128 4293853424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18521/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.304806 s]
/proc/loadavg: 1.14 1.01 0.87 5/39 18524
/proc/meminfo: memFree=776216/1048576 swapFree=0/0
[pid=18521] ppid=18520 vsize=2592 CPUtime=0
/proc/18521/stat : 18521 (aspuncud-user-1) S 18520 18521 17511 34816 17511 4202496 572 1521 0 0 0 0 0 0 25 0 1 0 46015367 2654208 298 1283457024 134512640 135304128 4293853424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18521/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.70487 s]
/proc/loadavg: 1.14 1.01 0.87 5/39 18524
/proc/meminfo: memFree=776216/1048576 swapFree=0/0
[pid=18521] ppid=18520 vsize=2592 CPUtime=0
/proc/18521/stat : 18521 (aspuncud-user-1) S 18520 18521 17511 34816 17511 4202496 572 1521 0 0 0 0 0 0 25 0 1 0 46015367 2654208 298 1283457024 134512640 135304128 4293853424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18521/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.5053 s]
/proc/loadavg: 1.45 1.08 0.89 2/40 18532
/proc/meminfo: memFree=754272/1048576 swapFree=0/0
[pid=18521] ppid=18520 vsize=2592 CPUtime=0
/proc/18521/stat : 18521 (aspuncud-user-1) S 18520 18521 17511 34816 17511 4202496 572 1521 0 0 0 0 0 0 25 0 1 0 46015367 2654208 298 1283457024 134512640 135304128 4293853424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18521/statm: 648 298 251 194 0 35 0
[pid=18530] ppid=18521 vsize=3444 CPUtime=0
/proc/18530/stat : 18530 (unclasp) S 18521 18521 17511 34816 17511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 46015368 3526656 272 1283457024 134512640 135121179 4294365664 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/18530/statm: 861 272 240 149 0 52 0
[pid=18531] ppid=18521 vsize=2688 CPUtime=0
/proc/18531/stat : 18531 (gringo) S 18521 18521 17511 34816 17511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 46015368 2752512 280 1283457024 134512640 137056543 4291001904 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/18531/statm: 672 280 252 622 0 47 0
[pid=18532] ppid=18521 vsize=25004 CPUtime=1.5
/proc/18532/stat : 18532 (cudf2lp) R 18521 18521 17511 34816 17511 4202496 7211 0 0 0 144 6 0 0 25 0 1 0 46015368 25604096 5618 1283457024 134512640 135786343 4288377888 18446744073709551615 135052145 0 0 6 0 0 0 0 17 0 0 0 0
/proc/18532/statm: 6251 5618 128 311 0 5938 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 33728

[startup+3.10583 s]
/proc/loadavg: 1.45 1.08 0.89 2/40 18532
/proc/meminfo: memFree=735548/1048576 swapFree=0/0
[pid=18521] ppid=18520 vsize=2592 CPUtime=2.39
/proc/18521/stat : 18521 (aspuncud-user-1) S 18520 18521 17511 34816 17511 4202496 573 14468 0 0 0 0 231 8 18 0 1 0 46015367 2654208 298 1283457024 134512640 135304128 4293853424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18521/statm: 648 298 251 194 0 35 0
[pid=18530] ppid=18521 vsize=16308 CPUtime=0.07
/proc/18530/stat : 18530 (unclasp) R 18521 18521 17511 34816 17511 4202496 3932 0 0 0 7 0 0 0 18 0 1 0 46015368 16699392 3502 1283457024 134512640 135121179 4294365664 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/18530/statm: 4077 3502 277 149 0 3268 0
[pid=18531] ppid=18521 vsize=23092 CPUtime=0.61
/proc/18531/stat : 18531 (gringo) R 18521 18521 17511 34816 17511 4202496 6216 0 0 0 59 2 0 0 18 0 1 0 46015368 23646208 4270 1283457024 134512640 137056543 4291001904 18446744073709551615 136246442 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/18531/statm: 5773 4270 268 622 0 5148 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 41992

[startup+6.3072 s]
/proc/loadavg: 1.42 1.08 0.89 2/38 18532
/proc/meminfo: memFree=753792/1048576 swapFree=0/0
[pid=18521] ppid=18520 vsize=2592 CPUtime=3.14
/proc/18521/stat : 18521 (aspuncud-user-1) S 18520 18521 17511 34816 17511 4202496 573 21712 0 0 0 0 300 14 16 0 1 0 46015367 2654208 298 1283457024 134512640 135304128 4293853424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18521/statm: 648 298 251 194 0 35 0
[pid=18530] ppid=18521 vsize=27240 CPUtime=3.15
/proc/18530/stat : 18530 (unclasp) R 18521 18521 17511 34816 17511 4202496 30876 0 0 0 301 14 0 0 25 0 1 0 46015368 27893760 5976 1283457024 134512640 135121179 4294365664 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/18530/statm: 6810 5976 321 149 0 6001 0
Current children cumulated CPU time (s) 6.29
Current children cumulated vsize (KiB) 29832

[startup+12.7096 s]
/proc/loadavg: 1.38 1.08 0.89 2/38 18534
/proc/meminfo: memFree=753296/1048576 swapFree=0/0
[pid=18521] ppid=18520 vsize=2592 CPUtime=3.14
/proc/18521/stat : 18521 (aspuncud-user-1) S 18520 18521 17511 34816 17511 4202496 573 21712 0 0 0 0 300 14 16 0 1 0 46015367 2654208 298 1283457024 134512640 135304128 4293853424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18521/statm: 648 298 251 194 0 35 0
[pid=18530] ppid=18521 vsize=26712 CPUtime=9.51
/proc/18530/stat : 18530 (unclasp) R 18521 18521 17511 34816 17511 4202496 80910 0 0 0 913 38 0 0 25 0 1 0 46015368 27353088 5850 1283457024 134512640 135121179 4294365664 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/18530/statm: 6678 5850 326 149 0 5869 0
Current children cumulated CPU time (s) 12.65
Current children cumulated vsize (KiB) 29304

[startup+25.5044 s]
/proc/loadavg: 1.30 1.07 0.89 2/38 18538
/proc/meminfo: memFree=753312/1048576 swapFree=0/0
[pid=18521] ppid=18520 vsize=2592 CPUtime=3.14
/proc/18521/stat : 18521 (aspuncud-user-1) S 18520 18521 17511 34816 17511 4202496 573 21712 0 0 0 0 300 14 16 0 1 0 46015367 2654208 298 1283457024 134512640 135304128 4293853424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18521/statm: 648 298 251 194 0 35 0
[pid=18530] ppid=18521 vsize=26712 CPUtime=22.27
/proc/18530/stat : 18530 (unclasp) R 18521 18521 17511 34816 17511 4202496 186906 0 0 0 2141 86 0 0 25 0 1 0 46015368 27353088 5850 1283457024 134512640 135121179 4294365664 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/18530/statm: 6678 5850 326 149 0 5869 0
Current children cumulated CPU time (s) 25.41
Current children cumulated vsize (KiB) 29304

Solver just ended. Dumping a history of the last processes samples

[startup+25.6044 s]
/proc/loadavg: 1.30 1.07 0.89 2/38 18538
/proc/meminfo: memFree=753312/1048576 swapFree=0/0
[pid=18521] ppid=18520 vsize=2592 CPUtime=3.14
/proc/18521/stat : 18521 (aspuncud-user-1) S 18520 18521 17511 34816 17511 4202496 573 21712 0 0 0 0 300 14 16 0 1 0 46015367 2654208 298 1283457024 134512640 135304128 4293853424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18521/statm: 648 298 251 194 0 35 0
[pid=18530] ppid=18521 vsize=26712 CPUtime=22.37
/proc/18530/stat : 18530 (unclasp) R 18521 18521 17511 34816 17511 4202496 187698 0 0 0 2151 86 0 0 25 0 1 0 46015368 27353088 5850 1283457024 134512640 135121179 4294365664 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/18530/statm: 6678 5850 326 149 0 5869 0
Current children cumulated CPU time (s) 25.51
Current children cumulated vsize (KiB) 29304

[startup+27.2051 s]
/proc/loadavg: 1.30 1.07 0.89 2/38 18538
/proc/meminfo: memFree=753312/1048576 swapFree=0/0
[pid=18521] ppid=18520 vsize=2592 CPUtime=3.14
/proc/18521/stat : 18521 (aspuncud-user-1) S 18520 18521 17511 34816 17511 4202496 573 21712 0 0 0 0 300 14 16 0 1 0 46015367 2654208 298 1283457024 134512640 135304128 4293853424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18521/statm: 648 298 251 194 0 35 0
[pid=18530] ppid=18521 vsize=26712 CPUtime=23.97
/proc/18530/stat : 18530 (unclasp) R 18521 18521 17511 34816 17511 4202496 201030 0 0 0 2305 92 0 0 25 0 1 0 46015368 27353088 5850 1283457024 134512640 135121179 4294365664 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/18530/statm: 6678 5850 326 149 0 5869 0
Current children cumulated CPU time (s) 27.11
Current children cumulated vsize (KiB) 29304

[startup+28.8058 s]
/proc/loadavg: 1.30 1.07 0.89 2/38 18538
/proc/meminfo: memFree=753172/1048576 swapFree=0/0
[pid=18521] ppid=18520 vsize=2592 CPUtime=3.14
/proc/18521/stat : 18521 (aspuncud-user-1) S 18520 18521 17511 34816 17511 4202496 573 21712 0 0 0 0 300 14 16 0 1 0 46015367 2654208 298 1283457024 134512640 135304128 4293853424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18521/statm: 648 298 251 194 0 35 0
[pid=18530] ppid=18521 vsize=27240 CPUtime=25.57
/proc/18530/stat : 18530 (unclasp) R 18521 18521 17511 34816 17511 4202496 214494 0 0 0 2457 100 0 0 25 0 1 0 46015368 27893760 5982 1283457024 134512640 135121179 4294365664 18446744073709551615 134981267 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/18530/statm: 6810 5982 326 149 0 6001 0
Current children cumulated CPU time (s) 28.71
Current children cumulated vsize (KiB) 29832

[startup+29.6061 s]
/proc/loadavg: 1.30 1.07 0.89 2/38 18538
/proc/meminfo: memFree=753172/1048576 swapFree=0/0
[pid=18521] ppid=18520 vsize=2592 CPUtime=3.14
/proc/18521/stat : 18521 (aspuncud-user-1) S 18520 18521 17511 34816 17511 4202496 573 21712 0 0 0 0 300 14 16 0 1 0 46015367 2654208 298 1283457024 134512640 135304128 4293853424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18521/statm: 648 298 251 194 0 35 0
[pid=18530] ppid=18521 vsize=27240 CPUtime=26.37
/proc/18530/stat : 18530 (unclasp) R 18521 18521 17511 34816 17511 4202496 221226 0 0 0 2534 103 0 0 25 0 1 0 46015368 27893760 5982 1283457024 134512640 135121179 4294365664 18446744073709551615 134981002 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/18530/statm: 6810 5982 326 149 0 6001 0
Current children cumulated CPU time (s) 29.51
Current children cumulated vsize (KiB) 29832

[startup+30.0063 s]
/proc/loadavg: 1.30 1.07 0.89 4/38 18538
/proc/meminfo: memFree=753172/1048576 swapFree=0/0
[pid=18521] ppid=18520 vsize=2592 CPUtime=3.14
/proc/18521/stat : 18521 (aspuncud-user-1) S 18520 18521 17511 34816 17511 4202496 573 21712 0 0 0 0 300 14 16 0 1 0 46015367 2654208 298 1283457024 134512640 135304128 4293853424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18521/statm: 648 298 251 194 0 35 0
[pid=18530] ppid=18521 vsize=27240 CPUtime=26.76
/proc/18530/stat : 18530 (unclasp) R 18521 18521 17511 34816 17511 4202496 224526 0 0 0 2573 103 0 0 25 0 1 0 46015368 27893760 5982 1283457024 134512640 135121179 4294365664 18446744073709551615 134981267 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/18530/statm: 6810 5982 326 149 0 6001 0
Current children cumulated CPU time (s) 29.9
Current children cumulated vsize (KiB) 29832

[startup+30.1063 s]
/proc/loadavg: 1.30 1.07 0.89 4/38 18538
/proc/meminfo: memFree=753172/1048576 swapFree=0/0
[pid=18521] ppid=18520 vsize=2592 CPUtime=3.14
/proc/18521/stat : 18521 (aspuncud-user-1) S 18520 18521 17511 34816 17511 4202496 573 21712 0 0 0 0 300 14 16 0 1 0 46015367 2654208 298 1283457024 134512640 135304128 4293853424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18521/statm: 648 298 251 194 0 35 0
[pid=18530] ppid=18521 vsize=26712 CPUtime=26.86
/proc/18530/stat : 18530 (unclasp) R 18521 18521 17511 34816 17511 4202496 225318 0 0 0 2581 105 0 0 25 0 1 0 46015368 27353088 5850 1283457024 134512640 135121179 4294365664 18446744073709551615 134643448 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/18530/statm: 6678 5850 326 149 0 5869 0
Current children cumulated CPU time (s) 30
Current children cumulated vsize (KiB) 29304

Child status: 0
Real time (s): 30.1487
CPU time (s): 30.0539
CPU user time (s): 28.8338
CPU system time (s): 1.22008
CPU usage (%): 99.6854
Max. virtual memory (cumulated for all children) (KiB): 67516

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 28.8338
system time used= 1.22008
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 250223
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= 1215
involuntary context switches= 1356

runsolver used 0 second user time and 0.008 second system time

The end