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/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/201108291842/aspuncud-user-1.0/ed1cc19e-51b7-11e0-8436-00163e1e087d.cudf.dudf-real.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.25 1.18 1.13 5/36 31567
/proc/meminfo: memFree=573020/1048576 swapFree=0/0
[pid=31566] ppid=31565 vsize=2588 CPUtime=0
/proc/31566/stat : 31566 (aspuncud-user-1) R 31565 31566 17511 34816 17511 4202496 367 0 0 0 0 0 0 0 25 0 1 0 46672953 2650112 280 1283457024 134512640 135304128 4290237760 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/31566/statm: 647 280 234 194 0 34 0
[pid=31567] ppid=31566 vsize=2588 CPUtime=0
/proc/31567/stat : 31567 (aspuncud-user-1) R 31566 31566 17511 34816 17511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 46672954 2650112 46 1283457024 134512640 135304128 4290237760 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/31567/statm: 647 46 0 194 0 34 0

[startup+0.125303 s]
/proc/loadavg: 1.25 1.18 1.13 5/36 31567
/proc/meminfo: memFree=573020/1048576 swapFree=0/0
[pid=31566] ppid=31565 vsize=2592 CPUtime=0
/proc/31566/stat : 31566 (aspuncud-user-1) S 31565 31566 17511 34816 17511 4202496 574 1520 0 0 0 0 0 0 25 0 1 0 46672953 2654208 298 1283457024 134512640 135304128 4290237760 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31566/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.20531 s]
/proc/loadavg: 1.25 1.18 1.13 5/36 31567
/proc/meminfo: memFree=573020/1048576 swapFree=0/0
[pid=31566] ppid=31565 vsize=2592 CPUtime=0
/proc/31566/stat : 31566 (aspuncud-user-1) S 31565 31566 17511 34816 17511 4202496 574 1520 0 0 0 0 0 0 25 0 1 0 46672953 2654208 298 1283457024 134512640 135304128 4290237760 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31566/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.305341 s]
/proc/loadavg: 1.25 1.18 1.13 5/36 31567
/proc/meminfo: memFree=573020/1048576 swapFree=0/0
[pid=31566] ppid=31565 vsize=2592 CPUtime=0
/proc/31566/stat : 31566 (aspuncud-user-1) S 31565 31566 17511 34816 17511 4202496 574 1520 0 0 0 0 0 0 25 0 1 0 46672953 2654208 298 1283457024 134512640 135304128 4290237760 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31566/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.705422 s]
/proc/loadavg: 1.25 1.18 1.13 5/36 31567
/proc/meminfo: memFree=573020/1048576 swapFree=0/0
[pid=31566] ppid=31565 vsize=2592 CPUtime=0
/proc/31566/stat : 31566 (aspuncud-user-1) S 31565 31566 17511 34816 17511 4202496 574 1520 0 0 0 0 0 0 25 0 1 0 46672953 2654208 298 1283457024 134512640 135304128 4290237760 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31566/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.50568 s]
/proc/loadavg: 1.25 1.18 1.13 2/39 31578
/proc/meminfo: memFree=551152/1048576 swapFree=0/0
[pid=31566] ppid=31565 vsize=2592 CPUtime=0
/proc/31566/stat : 31566 (aspuncud-user-1) S 31565 31566 17511 34816 17511 4202496 574 1520 0 0 0 0 0 0 25 0 1 0 46672953 2654208 298 1283457024 134512640 135304128 4290237760 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31566/statm: 648 298 251 194 0 35 0
[pid=31575] ppid=31566 vsize=5548 CPUtime=0.01
/proc/31575/stat : 31575 (unclasp) S 31566 31566 17511 34816 17511 4202496 983 0 0 0 1 0 0 0 18 0 1 0 46672955 5681152 847 1283457024 134512640 135121179 4289889696 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/31575/statm: 1387 847 275 149 0 578 0
[pid=31576] ppid=31566 vsize=5992 CPUtime=0.1
/proc/31576/stat : 31576 (gringo) R 31566 31566 17511 34816 17511 4202496 1345 0 0 0 9 1 0 0 18 0 1 0 46672955 6135808 941 1283457024 134512640 137056543 4289942832 18446744073709551615 136295052 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31576/statm: 1498 941 253 622 0 873 0
[pid=31577] ppid=31566 vsize=30772 CPUtime=1.36
/proc/31577/stat : 31577 (cudf2lp) R 31566 31566 17511 34816 17511 4202496 10039 0 0 0 134 2 0 0 25 0 1 0 46672955 31510528 7491 1283457024 134512640 135786343 4293279936 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/31577/statm: 7693 7491 139 311 0 7380 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 44904

[startup+3.10627 s]
/proc/loadavg: 1.25 1.18 1.13 2/37 31578
/proc/meminfo: memFree=558872/1048576 swapFree=0/0
[pid=31566] ppid=31565 vsize=2592 CPUtime=1.83
/proc/31566/stat : 31566 (aspuncud-user-1) S 31565 31566 17511 34816 17511 4202496 574 15905 0 0 0 0 176 7 17 0 1 0 46672953 2654208 298 1283457024 134512640 135304128 4290237760 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31566/statm: 648 298 251 194 0 35 0
[pid=31575] ppid=31566 vsize=17248 CPUtime=1.26
/proc/31575/stat : 31575 (unclasp) R 31566 31566 17511 34816 17511 4202496 13853 0 0 0 122 4 0 0 19 0 1 0 46672955 17661952 3633 1283457024 134512640 135121179 4289889696 18446744073709551615 134981273 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31575/statm: 4312 3633 328 149 0 3503 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 19840

[startup+6.30764 s]
/proc/loadavg: 1.23 1.17 1.13 2/37 31578
/proc/meminfo: memFree=559368/1048576 swapFree=0/0
[pid=31566] ppid=31565 vsize=2592 CPUtime=1.83
/proc/31566/stat : 31566 (aspuncud-user-1) S 31565 31566 17511 34816 17511 4202496 574 15905 0 0 0 0 176 7 17 0 1 0 46672953 2654208 298 1283457024 134512640 135304128 4290237760 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31566/statm: 648 298 251 194 0 35 0
[pid=31575] ppid=31566 vsize=17016 CPUtime=4.46
/proc/31575/stat : 31575 (unclasp) R 31566 31566 17511 34816 17511 4202496 47960 0 0 0 426 20 0 0 25 0 1 0 46672955 17424384 3608 1283457024 134512640 135121179 4289889696 18446744073709551615 134981267 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31575/statm: 4254 3608 328 149 0 3445 0
Current children cumulated CPU time (s) 6.29
Current children cumulated vsize (KiB) 19608

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

[startup+6.40767 s]
/proc/loadavg: 1.23 1.17 1.13 2/37 31578
/proc/meminfo: memFree=559368/1048576 swapFree=0/0
[pid=31566] ppid=31565 vsize=2592 CPUtime=1.83
/proc/31566/stat : 31566 (aspuncud-user-1) S 31565 31566 17511 34816 17511 4202496 574 15905 0 0 0 0 176 7 17 0 1 0 46672953 2654208 298 1283457024 134512640 135304128 4290237760 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31566/statm: 648 298 251 194 0 35 0
[pid=31575] ppid=31566 vsize=17016 CPUtime=4.56
/proc/31575/stat : 31575 (unclasp) R 31566 31566 17511 34816 17511 4202496 49041 0 0 0 436 20 0 0 25 0 1 0 46672955 17424384 3585 1283457024 134512640 135121179 4289889696 18446744073709551615 134981267 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31575/statm: 4254 3585 328 149 0 3445 0
Current children cumulated CPU time (s) 6.39
Current children cumulated vsize (KiB) 19608

[startup+9.6088 s]
/proc/loadavg: 1.23 1.17 1.13 2/37 31578
/proc/meminfo: memFree=559376/1048576 swapFree=0/0
[pid=31566] ppid=31565 vsize=2592 CPUtime=1.83
/proc/31566/stat : 31566 (aspuncud-user-1) S 31565 31566 17511 34816 17511 4202496 574 15905 0 0 0 0 176 7 17 0 1 0 46672953 2654208 298 1283457024 134512640 135304128 4290237760 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31566/statm: 648 298 251 194 0 35 0
[pid=31575] ppid=31566 vsize=17016 CPUtime=7.76
/proc/31575/stat : 31575 (unclasp) R 31566 31566 17511 34816 17511 4202496 84001 0 0 0 738 38 0 0 25 0 1 0 46672955 17424384 3585 1283457024 134512640 135121179 4289889696 18446744073709551615 134983118 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31575/statm: 4254 3585 328 149 0 3445 0
Current children cumulated CPU time (s) 9.59
Current children cumulated vsize (KiB) 19608

[startup+10.4091 s]
/proc/loadavg: 1.21 1.17 1.13 2/37 31578
/proc/meminfo: memFree=559376/1048576 swapFree=0/0
[pid=31566] ppid=31565 vsize=2592 CPUtime=1.83
/proc/31566/stat : 31566 (aspuncud-user-1) S 31565 31566 17511 34816 17511 4202496 574 15905 0 0 0 0 176 7 17 0 1 0 46672953 2654208 298 1283457024 134512640 135304128 4290237760 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31566/statm: 648 298 251 194 0 35 0
[pid=31575] ppid=31566 vsize=16712 CPUtime=8.56
/proc/31575/stat : 31575 (unclasp) R 31566 31566 17511 34816 17511 4202496 92605 0 0 0 814 42 0 0 25 0 1 0 46672955 17113088 3541 1283457024 134512640 135121179 4289889696 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31575/statm: 4178 3541 328 149 0 3369 0
Current children cumulated CPU time (s) 10.39
Current children cumulated vsize (KiB) 19304

[startup+10.8093 s]
/proc/loadavg: 1.21 1.17 1.13 2/37 31578
/proc/meminfo: memFree=559376/1048576 swapFree=0/0
[pid=31566] ppid=31565 vsize=2592 CPUtime=1.83
/proc/31566/stat : 31566 (aspuncud-user-1) S 31565 31566 17511 34816 17511 4202496 574 15905 0 0 0 0 176 7 17 0 1 0 46672953 2654208 298 1283457024 134512640 135304128 4290237760 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31566/statm: 648 298 251 194 0 35 0
[pid=31575] ppid=31566 vsize=16712 CPUtime=8.96
/proc/31575/stat : 31575 (unclasp) R 31566 31566 17511 34816 17511 4202496 97021 0 0 0 851 45 0 0 25 0 1 0 46672955 17113088 3541 1283457024 134512640 135121179 4289889696 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31575/statm: 4178 3541 328 149 0 3369 0
Current children cumulated CPU time (s) 10.79
Current children cumulated vsize (KiB) 19304

[startup+11.0094 s]
/proc/loadavg: 1.21 1.17 1.13 2/37 31579
/proc/meminfo: memFree=559376/1048576 swapFree=0/0
[pid=31566] ppid=31565 vsize=2592 CPUtime=1.83
/proc/31566/stat : 31566 (aspuncud-user-1) S 31565 31566 17511 34816 17511 4202496 574 15905 0 0 0 0 176 7 17 0 1 0 46672953 2654208 298 1283457024 134512640 135304128 4290237760 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31566/statm: 648 298 251 194 0 35 0
[pid=31575] ppid=31566 vsize=16712 CPUtime=9.16
/proc/31575/stat : 31575 (unclasp) R 31566 31566 17511 34816 17511 4202496 99229 0 0 0 870 46 0 0 25 0 1 0 46672955 17113088 3541 1283457024 134512640 135121179 4289889696 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31575/statm: 4178 3541 328 149 0 3369 0
Current children cumulated CPU time (s) 10.99
Current children cumulated vsize (KiB) 19304

Child status: 0
Real time (s): 11.0946
CPU time (s): 11.0887
CPU user time (s): 10.5447
CPU system time (s): 0.544034
CPU usage (%): 99.9469
Max. virtual memory (cumulated for all children) (KiB): 48100

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 10.5447
system time used= 0.544034
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 118958
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= 662
involuntary context switches= 612

runsolver used 0 second user time and 0 second system time

The end