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/rand192.cudf.dudf-random.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-random//rand192.cudf /home/misc2010/tmp/201108291842/aspuncud-user-1.0/rand192.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.10 0.59 0.71 5/38 17612
/proc/meminfo: memFree=457576/1048576 swapFree=0/0
[pid=17609] ppid=17608 vsize=2588 CPUtime=0
/proc/17609/stat : 17609 (aspuncud-user-1) S 17608 17609 17511 34816 17511 4202496 373 0 0 0 0 0 0 0 22 0 1 0 45951717 2650112 280 1283457024 134512640 135304128 4293619888 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/17609/statm: 647 280 234 194 0 34 0
[pid=17610] ppid=17609 vsize=2588 CPUtime=0
/proc/17610/stat : 17610 (aspuncud-user-1) S 17609 17609 17511 34816 17511 4202560 118 0 0 0 0 0 0 0 22 0 1 0 45951717 2650112 134 1283457024 134512640 135304128 4293619888 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/17610/statm: 647 134 87 194 0 34 0
[pid=17611] ppid=17610 vsize=2588 CPUtime=0.01
/proc/17611/stat : 17611 (aspuncud-user-1) R 17610 17609 17511 34816 17511 4202560 127 0 0 0 0 1 0 0 25 0 1 0 45951717 2650112 151 1283457024 134512640 135304128 4293619888 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/17611/statm: 647 151 104 194 0 34 0
[pid=17612] ppid=17611 vsize=2588 CPUtime=0
/proc/17612/stat : 17612 (aspuncud-user-1) R 17611 17609 17511 34816 17511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 45951717 2650112 47 1283457024 134512640 135304128 4293619888 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/17612/statm: 647 47 0 194 0 34 0

[startup+0.152828 s]
/proc/loadavg: 1.10 0.59 0.71 5/38 17612
/proc/meminfo: memFree=457576/1048576 swapFree=0/0
[pid=17609] ppid=17608 vsize=2592 CPUtime=0.01
/proc/17609/stat : 17609 (aspuncud-user-1) S 17608 17609 17511 34816 17511 4202496 571 1522 0 0 0 0 0 1 25 0 1 0 45951717 2654208 298 1283457024 134512640 135304128 4293619888 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17609/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.20283 s]
/proc/loadavg: 1.10 0.59 0.71 5/38 17612
/proc/meminfo: memFree=457576/1048576 swapFree=0/0
[pid=17609] ppid=17608 vsize=2592 CPUtime=0.01
/proc/17609/stat : 17609 (aspuncud-user-1) S 17608 17609 17511 34816 17511 4202496 571 1522 0 0 0 0 0 1 25 0 1 0 45951717 2654208 298 1283457024 134512640 135304128 4293619888 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17609/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.312846 s]
/proc/loadavg: 1.10 0.59 0.71 5/38 17612
/proc/meminfo: memFree=457576/1048576 swapFree=0/0
[pid=17609] ppid=17608 vsize=2592 CPUtime=0.01
/proc/17609/stat : 17609 (aspuncud-user-1) S 17608 17609 17511 34816 17511 4202496 571 1522 0 0 0 0 0 1 25 0 1 0 45951717 2654208 298 1283457024 134512640 135304128 4293619888 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17609/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.712892 s]
/proc/loadavg: 1.10 0.59 0.71 5/38 17612
/proc/meminfo: memFree=457576/1048576 swapFree=0/0
[pid=17609] ppid=17608 vsize=2592 CPUtime=0.01
/proc/17609/stat : 17609 (aspuncud-user-1) S 17608 17609 17511 34816 17511 4202496 571 1522 0 0 0 0 0 1 25 0 1 0 45951717 2654208 298 1283457024 134512640 135304128 4293619888 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17609/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+1.51299 s]
/proc/loadavg: 1.10 0.59 0.71 2/39 17620
/proc/meminfo: memFree=435536/1048576 swapFree=0/0
[pid=17609] ppid=17608 vsize=2592 CPUtime=0.01
/proc/17609/stat : 17609 (aspuncud-user-1) S 17608 17609 17511 34816 17511 4202496 571 1522 0 0 0 0 0 1 25 0 1 0 45951717 2654208 298 1283457024 134512640 135304128 4293619888 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17609/statm: 648 298 251 194 0 35 0
[pid=17618] ppid=17609 vsize=3444 CPUtime=0
/proc/17618/stat : 17618 (unclasp) S 17609 17609 17511 34816 17511 4202496 406 0 0 0 0 0 0 0 25 0 1 0 45951718 3526656 271 1283457024 134512640 135121179 4289055952 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/17618/statm: 861 271 240 149 0 52 0
[pid=17619] ppid=17609 vsize=2696 CPUtime=0
/proc/17619/stat : 17619 (gringo) S 17609 17609 17511 34816 17511 4202496 408 0 0 0 0 0 0 0 25 0 1 0 45951718 2760704 281 1283457024 134512640 137056543 4294150448 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/17619/statm: 674 281 252 622 0 49 0
[pid=17620] ppid=17609 vsize=25008 CPUtime=1.5
/proc/17620/stat : 17620 (cudf2lp) R 17609 17609 17511 34816 17511 4202496 7220 0 0 0 144 6 0 0 25 0 1 0 45951718 25608192 5627 1283457024 134512640 135786343 4293941600 18446744073709551615 134566184 0 0 6 0 0 0 0 17 0 0 0 0
/proc/17620/statm: 6252 5627 128 311 0 5939 0
Current children cumulated CPU time (s) 1.51
Current children cumulated vsize (KiB) 33740

[startup+3.11328 s]
/proc/loadavg: 1.09 0.60 0.71 3/39 17620
/proc/meminfo: memFree=417060/1048576 swapFree=0/0
[pid=17609] ppid=17608 vsize=2592 CPUtime=2.41
/proc/17609/stat : 17609 (aspuncud-user-1) S 17608 17609 17511 34816 17511 4202496 572 14424 0 0 0 0 225 16 18 0 1 0 45951717 2654208 298 1283457024 134512640 135304128 4293619888 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17609/statm: 648 298 251 194 0 35 0
[pid=17618] ppid=17609 vsize=16052 CPUtime=0.08
/proc/17618/stat : 17618 (unclasp) R 17609 17609 17511 34816 17511 4202496 3923 0 0 0 8 0 0 0 18 0 1 0 45951718 16437248 3402 1283457024 134512640 135121179 4289055952 18446744073709551615 134744496 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/17618/statm: 4013 3402 277 149 0 3204 0
[pid=17619] ppid=17609 vsize=23104 CPUtime=0.6
/proc/17619/stat : 17619 (gringo) R 17609 17609 17511 34816 17511 4202496 6455 0 0 0 60 0 0 0 18 0 1 0 45951718 23658496 4380 1283457024 134512640 137056543 4294150448 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/17619/statm: 5776 4380 268 622 0 5151 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 41748

[startup+6.31461 s]
/proc/loadavg: 1.09 0.60 0.71 2/37 17621
/proc/meminfo: memFree=432220/1048576 swapFree=0/0
[pid=17609] ppid=17608 vsize=2592 CPUtime=3.18
/proc/17609/stat : 17609 (aspuncud-user-1) S 17608 17609 17511 34816 17511 4202496 572 22186 0 0 0 0 300 18 16 0 1 0 45951717 2654208 298 1283457024 134512640 135304128 4293619888 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17609/statm: 648 298 251 194 0 35 0
[pid=17618] ppid=17609 vsize=30060 CPUtime=3.12
/proc/17618/stat : 17618 (unclasp) R 17609 17609 17511 34816 17511 4202496 14100 0 0 0 307 5 0 0 25 0 1 0 45951718 30781440 6624 1283457024 134512640 135121179 4289055952 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/17618/statm: 7515 6624 333 149 0 6706 0
Current children cumulated CPU time (s) 6.3
Current children cumulated vsize (KiB) 32652

[startup+12.707 s]
/proc/loadavg: 1.08 0.61 0.72 2/37 17621
/proc/meminfo: memFree=432228/1048576 swapFree=0/0
[pid=17609] ppid=17608 vsize=2592 CPUtime=3.18
/proc/17609/stat : 17609 (aspuncud-user-1) S 17608 17609 17511 34816 17511 4202496 572 22186 0 0 0 0 300 18 16 0 1 0 45951717 2654208 298 1283457024 134512640 135304128 4293619888 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17609/statm: 648 298 251 194 0 35 0
[pid=17618] ppid=17609 vsize=29984 CPUtime=9.5
/proc/17618/stat : 17618 (unclasp) R 17609 17609 17511 34816 17511 4202496 56143 0 0 0 920 30 0 0 25 0 1 0 45951718 30703616 6610 1283457024 134512640 135121179 4289055952 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/17618/statm: 7496 6610 333 149 0 6687 0
Current children cumulated CPU time (s) 12.68
Current children cumulated vsize (KiB) 32576

[startup+25.5119 s]
/proc/loadavg: 1.06 0.62 0.72 2/36 17622
/proc/meminfo: memFree=432492/1048576 swapFree=0/0
[pid=17609] ppid=17608 vsize=2592 CPUtime=3.18
/proc/17609/stat : 17609 (aspuncud-user-1) S 17608 17609 17511 34816 17511 4202496 572 22186 0 0 0 0 300 18 16 0 1 0 45951717 2654208 298 1283457024 134512640 135304128 4293619888 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17609/statm: 648 298 251 194 0 35 0
[pid=17618] ppid=17609 vsize=29668 CPUtime=22.31
/proc/17618/stat : 17618 (unclasp) R 17609 17609 17511 34816 17511 4202496 74921 0 0 0 2190 41 0 0 25 0 1 0 45951718 30380032 6560 1283457024 134512640 135121179 4289055952 18446744073709551615 134990446 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/17618/statm: 7417 6560 333 149 0 6608 0
Current children cumulated CPU time (s) 25.49
Current children cumulated vsize (KiB) 32260

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

[startup+25.6119 s]
/proc/loadavg: 1.06 0.62 0.72 2/36 17622
/proc/meminfo: memFree=432492/1048576 swapFree=0/0
[pid=17609] ppid=17608 vsize=2592 CPUtime=3.18
/proc/17609/stat : 17609 (aspuncud-user-1) S 17608 17609 17511 34816 17511 4202496 572 22186 0 0 0 0 300 18 16 0 1 0 45951717 2654208 298 1283457024 134512640 135304128 4293619888 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17609/statm: 648 298 251 194 0 35 0
[pid=17618] ppid=17609 vsize=29108 CPUtime=22.41
/proc/17618/stat : 17618 (unclasp) R 17609 17609 17511 34816 17511 4202496 75624 0 0 0 2198 43 0 0 25 0 1 0 45951718 29806592 6423 1283457024 134512640 135121179 4289055952 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/17618/statm: 7277 6423 333 149 0 6468 0
Current children cumulated CPU time (s) 25.59
Current children cumulated vsize (KiB) 31700

[startup+32.0047 s]
/proc/loadavg: 1.05 0.63 0.72 2/36 17622
/proc/meminfo: memFree=432492/1048576 swapFree=0/0
[pid=17609] ppid=17608 vsize=2592 CPUtime=3.18
/proc/17609/stat : 17609 (aspuncud-user-1) S 17608 17609 17511 34816 17511 4202496 572 22186 0 0 0 0 300 18 16 0 1 0 45951717 2654208 298 1283457024 134512640 135304128 4293619888 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17609/statm: 648 298 251 194 0 35 0
[pid=17618] ppid=17609 vsize=29928 CPUtime=28.79
/proc/17618/stat : 17618 (unclasp) R 17609 17609 17511 34816 17511 4202496 128521 0 0 0 2816 63 0 0 25 0 1 0 45951718 30646272 6540 1283457024 134512640 135121179 4289055952 18446744073709551615 134990455 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/17618/statm: 7482 6540 333 149 0 6673 0
Current children cumulated CPU time (s) 31.97
Current children cumulated vsize (KiB) 32520

[startup+38.407 s]
/proc/loadavg: 1.05 0.64 0.72 2/36 17622
/proc/meminfo: memFree=432368/1048576 swapFree=0/0
[pid=17609] ppid=17608 vsize=2592 CPUtime=3.18
/proc/17609/stat : 17609 (aspuncud-user-1) S 17608 17609 17511 34816 17511 4202496 572 22186 0 0 0 0 300 18 16 0 1 0 45951717 2654208 298 1283457024 134512640 135304128 4293619888 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17609/statm: 648 298 251 194 0 35 0
[pid=17618] ppid=17609 vsize=29368 CPUtime=35.18
/proc/17618/stat : 17618 (unclasp) R 17609 17609 17511 34816 17511 4202496 182192 0 0 0 3425 93 0 0 25 0 1 0 45951718 30072832 6451 1283457024 134512640 135121179 4289055952 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/17618/statm: 7342 6451 333 149 0 6533 0
Current children cumulated CPU time (s) 38.36
Current children cumulated vsize (KiB) 31960

[startup+41.6082 s]
/proc/loadavg: 1.05 0.64 0.72 2/36 17622
/proc/meminfo: memFree=432244/1048576 swapFree=0/0
[pid=17609] ppid=17608 vsize=2592 CPUtime=3.18
/proc/17609/stat : 17609 (aspuncud-user-1) S 17608 17609 17511 34816 17511 4202496 572 22186 0 0 0 0 300 18 16 0 1 0 45951717 2654208 298 1283457024 134512640 135304128 4293619888 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17609/statm: 648 298 251 194 0 35 0
[pid=17618] ppid=17609 vsize=29368 CPUtime=38.38
/proc/17618/stat : 17618 (unclasp) R 17609 17609 17511 34816 17511 4202496 209072 0 0 0 3732 106 0 0 25 0 1 0 45951718 30072832 6451 1283457024 134512640 135121179 4289055952 18446744073709551615 4159403077 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/17618/statm: 7342 6451 333 149 0 6533 0
Current children cumulated CPU time (s) 41.56
Current children cumulated vsize (KiB) 31960

[startup+43.2087 s]
/proc/loadavg: 1.05 0.64 0.72 2/36 17622
/proc/meminfo: memFree=432244/1048576 swapFree=0/0
[pid=17609] ppid=17608 vsize=2592 CPUtime=3.18
/proc/17609/stat : 17609 (aspuncud-user-1) S 17608 17609 17511 34816 17511 4202496 572 22186 0 0 0 0 300 18 16 0 1 0 45951717 2654208 298 1283457024 134512640 135304128 4293619888 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17609/statm: 648 298 251 194 0 35 0
[pid=17618] ppid=17609 vsize=29368 CPUtime=39.98
/proc/17618/stat : 17618 (unclasp) R 17609 17609 17511 34816 17511 4202496 222372 0 0 0 3884 114 0 0 25 0 1 0 45951718 30072832 6451 1283457024 134512640 135121179 4289055952 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/17618/statm: 7342 6451 333 149 0 6533 0
Current children cumulated CPU time (s) 43.16
Current children cumulated vsize (KiB) 31960

[startup+43.6089 s]
/proc/loadavg: 1.05 0.64 0.72 2/36 17622
/proc/meminfo: memFree=432244/1048576 swapFree=0/0
[pid=17609] ppid=17608 vsize=2592 CPUtime=3.18
/proc/17609/stat : 17609 (aspuncud-user-1) S 17608 17609 17511 34816 17511 4202496 572 22186 0 0 0 0 300 18 16 0 1 0 45951717 2654208 298 1283457024 134512640 135304128 4293619888 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17609/statm: 648 298 251 194 0 35 0
[pid=17618] ppid=17609 vsize=29368 CPUtime=40.38
/proc/17618/stat : 17618 (unclasp) R 17609 17609 17511 34816 17511 4202496 225452 0 0 0 3924 114 0 0 25 0 1 0 45951718 30072832 6451 1283457024 134512640 135121179 4289055952 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/17618/statm: 7342 6451 333 149 0 6533 0
Current children cumulated CPU time (s) 43.56
Current children cumulated vsize (KiB) 31960

[startup+44.0096 s]
/proc/loadavg: 1.05 0.64 0.72 3/36 17631
/proc/meminfo: memFree=456476/1048576 swapFree=0/0
[pid=17609] ppid=17608 vsize=2592 CPUtime=43.95
/proc/17609/stat : 17609 (aspuncud-user-1) R 17608 17609 17511 34816 17511 4202496 743 252333 0 0 0 0 4261 134 20 0 1 0 45951717 2654208 298 1283457024 134512640 135304128 4293619888 18446744073709551615 4294960130 0 65538 16902 1132543225 0 0 0 17 0 0 0 0
/proc/17609/statm: 648 298 251 194 0 35 0
[pid=17631] ppid=17609 vsize=48 CPUtime=0
/proc/17631/stat : 17631 (cat) R 17609 17609 17511 34816 17511 4194304 67 0 0 0 0 0 0 0 20 0 1 0 45956118 49152 2 1283457024 0 0 4290511756 18446744073709551615 4294960130 0 0 16898 0 0 0 0 17 0 0 0 0
/proc/17631/statm: 12 2 0 0 0 1 0
Current children cumulated CPU time (s) 43.95
Current children cumulated vsize (KiB) 2640

Child status: 0
Real time (s): 44.0138
CPU time (s): 43.9707
CPU user time (s): 42.6147
CPU system time (s): 1.35608
CPU usage (%): 99.9021
Max. virtual memory (cumulated for all children) (KiB): 70624

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 42.6147
system time used= 1.35608
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 253496
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= 1252
involuntary context switches= 1441

runsolver used 0 second user time and 0 second system time

The end