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/201109011757/aspuncud-user-1.0/4a69cf16-c731-11df-9182-00163e3d3b7c.cudf.dudf-real.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-real//4a69cf16-c731-11df-9182-00163e3d3b7c.cudf /home/misc2010/tmp/201109011757/aspuncud-user-1.0/4a69cf16-c731-11df-9182-00163e3d3b7c.cudf.dudf-real.result -sum(pin-priority-1),-sum(pin-priority-500),-sum(pin-priority-700),-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.00 1.03 1.01 5/34 28408
/proc/meminfo: memFree=277948/1048576 swapFree=0/0
[pid=28407] ppid=28406 vsize=2588 CPUtime=0
/proc/28407/stat : 28407 (aspuncud-user-1) R 28406 28407 22717 34817 22717 4202496 366 0 0 0 0 0 0 0 25 0 1 0 72478791 2650112 279 1283457024 134512640 135304128 4293855344 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/28407/statm: 647 279 234 194 0 34 0
[pid=28408] ppid=28407 vsize=2588 CPUtime=0
/proc/28408/stat : 28408 (aspuncud-user-1) R 28407 28407 22717 34817 22717 4202560 0 0 0 0 0 0 0 0 25 0 1 0 72478792 2650112 45 1283457024 134512640 135304128 4293855344 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/28408/statm: 647 45 0 194 0 34 0

[startup+0.134847 s]
/proc/loadavg: 1.00 1.03 1.01 5/34 28408
/proc/meminfo: memFree=277948/1048576 swapFree=0/0
[pid=28407] ppid=28406 vsize=2592 CPUtime=0.01
/proc/28407/stat : 28407 (aspuncud-user-1) S 28406 28407 22717 34817 22717 4202496 577 1519 0 0 0 0 0 1 25 0 1 0 72478791 2654208 297 1283457024 134512640 135304128 4293855344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28407/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.204856 s]
/proc/loadavg: 1.00 1.03 1.01 5/34 28408
/proc/meminfo: memFree=277948/1048576 swapFree=0/0
[pid=28407] ppid=28406 vsize=2592 CPUtime=0.01
/proc/28407/stat : 28407 (aspuncud-user-1) S 28406 28407 22717 34817 22717 4202496 577 1519 0 0 0 0 0 1 25 0 1 0 72478791 2654208 297 1283457024 134512640 135304128 4293855344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28407/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.304874 s]
/proc/loadavg: 1.00 1.03 1.01 5/34 28408
/proc/meminfo: memFree=277948/1048576 swapFree=0/0
[pid=28407] ppid=28406 vsize=2592 CPUtime=0.01
/proc/28407/stat : 28407 (aspuncud-user-1) S 28406 28407 22717 34817 22717 4202496 577 1519 0 0 0 0 0 1 25 0 1 0 72478791 2654208 297 1283457024 134512640 135304128 4293855344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28407/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.704967 s]
/proc/loadavg: 1.00 1.03 1.01 5/34 28408
/proc/meminfo: memFree=277948/1048576 swapFree=0/0
[pid=28407] ppid=28406 vsize=2592 CPUtime=0.01
/proc/28407/stat : 28407 (aspuncud-user-1) S 28406 28407 22717 34817 22717 4202496 577 1519 0 0 0 0 0 1 25 0 1 0 72478791 2654208 297 1283457024 134512640 135304128 4293855344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28407/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+1.5051 s]
/proc/loadavg: 1.00 1.03 1.01 2/37 28418
/proc/meminfo: memFree=253104/1048576 swapFree=0/0
[pid=28407] ppid=28406 vsize=2592 CPUtime=0.01
/proc/28407/stat : 28407 (aspuncud-user-1) S 28406 28407 22717 34817 22717 4202496 577 1519 0 0 0 0 0 1 25 0 1 0 72478791 2654208 297 1283457024 134512640 135304128 4293855344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28407/statm: 648 297 251 194 0 35 0
[pid=28416] ppid=28407 vsize=3448 CPUtime=0
/proc/28416/stat : 28416 (unclasp) S 28407 28407 22717 34817 22717 4202496 408 0 0 0 0 0 0 0 25 0 1 0 72478793 3530752 272 1283457024 134512640 135121179 4288705664 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/28416/statm: 862 272 240 149 0 53 0
[pid=28417] ppid=28407 vsize=2692 CPUtime=0
/proc/28417/stat : 28417 (gringo) S 28407 28407 22717 34817 22717 4202496 408 0 0 0 0 0 0 0 25 0 1 0 72478793 2756608 280 1283457024 134512640 137056543 4291456672 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/28417/statm: 673 280 252 622 0 48 0
[pid=28418] ppid=28407 vsize=28108 CPUtime=1.49
/proc/28418/stat : 28418 (cudf2lp) R 28407 28407 22717 34817 22717 4202496 8326 0 0 0 145 4 0 0 25 0 1 0 72478793 28782592 6586 1283457024 134512640 135786343 4287996800 18446744073709551615 135044512 0 0 6 0 0 0 0 17 0 0 0 0
/proc/28418/statm: 7027 6586 128 311 0 6714 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 36840

[startup+3.10547 s]
/proc/loadavg: 1.00 1.03 1.01 2/37 28418
/proc/meminfo: memFree=225700/1048576 swapFree=0/0
[pid=28407] ppid=28406 vsize=2592 CPUtime=2.03
/proc/28407/stat : 28407 (aspuncud-user-1) S 28406 28407 22717 34817 22717 4202496 577 14388 0 0 0 0 196 7 18 0 1 0 72478791 2654208 297 1283457024 134512640 135304128 4293855344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28407/statm: 648 297 251 194 0 35 0
[pid=28416] ppid=28407 vsize=24256 CPUtime=0.15
/proc/28416/stat : 28416 (unclasp) R 28407 28407 22717 34817 22717 4202496 6121 0 0 0 14 1 0 0 18 0 1 0 72478793 24838144 5463 1283457024 134512640 135121179 4288705664 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/28416/statm: 6064 5463 279 149 0 5255 0
[pid=28417] ppid=28407 vsize=36864 CPUtime=0.9
/proc/28417/stat : 28417 (gringo) R 28407 28407 22717 34817 22717 4202496 9342 0 0 0 89 1 0 0 18 0 1 0 72478793 37748736 7266 1283457024 134512640 137056543 4291456672 18446744073709551615 135969580 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/28417/statm: 9216 7266 268 622 0 8591 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 63712

[startup+6.3068 s]
/proc/loadavg: 1.08 1.04 1.02 2/35 28418
/proc/meminfo: memFree=246944/1048576 swapFree=0/0
[pid=28407] ppid=28406 vsize=2592 CPUtime=2.99
/proc/28407/stat : 28407 (aspuncud-user-1) S 28406 28407 22717 34817 22717 4202496 577 23733 0 0 0 0 290 9 15 0 1 0 72478791 2654208 297 1283457024 134512640 135304128 4293855344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28407/statm: 648 297 251 194 0 35 0
[pid=28416] ppid=28407 vsize=35704 CPUtime=3.3
/proc/28416/stat : 28416 (unclasp) R 28407 28407 22717 34817 22717 4202496 32460 0 0 0 318 12 0 0 25 0 1 0 72478793 36560896 7989 1283457024 134512640 135121179 4288705664 18446744073709551615 134981273 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/28416/statm: 8926 7989 326 149 0 8117 0
Current children cumulated CPU time (s) 6.29
Current children cumulated vsize (KiB) 38296

[startup+12.7091 s]
/proc/loadavg: 1.07 1.04 1.02 2/35 28418
/proc/meminfo: memFree=246944/1048576 swapFree=0/0
[pid=28407] ppid=28406 vsize=2592 CPUtime=2.99
/proc/28407/stat : 28407 (aspuncud-user-1) S 28406 28407 22717 34817 22717 4202496 577 23733 0 0 0 0 290 9 15 0 1 0 72478791 2654208 297 1283457024 134512640 135304128 4293855344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28407/statm: 648 297 251 194 0 35 0
[pid=28416] ppid=28407 vsize=35704 CPUtime=9.7
/proc/28416/stat : 28416 (unclasp) R 28407 28407 22717 34817 22717 4202496 87030 0 0 0 933 37 0 0 25 0 1 0 72478793 36560896 7989 1283457024 134512640 135121179 4288705664 18446744073709551615 134981273 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/28416/statm: 8926 7989 326 149 0 8117 0
Current children cumulated CPU time (s) 12.69
Current children cumulated vsize (KiB) 38296

[startup+25.5044 s]
/proc/loadavg: 1.06 1.04 1.02 2/35 28418
/proc/meminfo: memFree=246820/1048576 swapFree=0/0
[pid=28407] ppid=28406 vsize=2592 CPUtime=2.99
/proc/28407/stat : 28407 (aspuncud-user-1) S 28406 28407 22717 34817 22717 4202496 577 23733 0 0 0 0 290 9 15 0 1 0 72478791 2654208 297 1283457024 134512640 135304128 4293855344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28407/statm: 648 297 251 194 0 35 0
[pid=28416] ppid=28407 vsize=35024 CPUtime=22.49
/proc/28416/stat : 28416 (unclasp) R 28407 28407 22717 34817 22717 4202496 194980 0 0 0 2148 101 0 0 25 0 1 0 72478793 35864576 7819 1283457024 134512640 135121179 4288705664 18446744073709551615 134638692 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/28416/statm: 8756 7819 326 149 0 7947 0
Current children cumulated CPU time (s) 25.48
Current children cumulated vsize (KiB) 37616

[startup+51.1073 s]
/proc/loadavg: 1.04 1.04 1.01 2/35 28418
/proc/meminfo: memFree=246324/1048576 swapFree=0/0
[pid=28407] ppid=28406 vsize=2592 CPUtime=2.99
/proc/28407/stat : 28407 (aspuncud-user-1) S 28406 28407 22717 34817 22717 4202496 577 23733 0 0 0 0 290 9 15 0 1 0 72478791 2654208 297 1283457024 134512640 135304128 4293855344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28407/statm: 648 297 251 194 0 35 0
[pid=28416] ppid=28407 vsize=36020 CPUtime=48.06
/proc/28416/stat : 28416 (unclasp) R 28407 28407 22717 34817 22717 4202496 411118 0 0 0 4614 192 0 0 25 0 1 0 72478793 36884480 8057 1283457024 134512640 135121179 4288705664 18446744073709551615 134990474 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/28416/statm: 9005 8057 326 149 0 8196 0
Current children cumulated CPU time (s) 51.05
Current children cumulated vsize (KiB) 38612

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

[startup+51.2073 s]
/proc/loadavg: 1.04 1.04 1.01 2/35 28418
/proc/meminfo: memFree=246324/1048576 swapFree=0/0
[pid=28407] ppid=28406 vsize=2592 CPUtime=2.99
/proc/28407/stat : 28407 (aspuncud-user-1) S 28406 28407 22717 34817 22717 4202496 577 23733 0 0 0 0 290 9 15 0 1 0 72478791 2654208 297 1283457024 134512640 135304128 4293855344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28407/statm: 648 297 251 194 0 35 0
[pid=28416] ppid=28407 vsize=35340 CPUtime=48.16
/proc/28416/stat : 28416 (unclasp) R 28407 28407 22717 34817 22717 4202496 411808 0 0 0 4624 192 0 0 25 0 1 0 72478793 36188160 7897 1283457024 134512640 135121179 4288705664 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/28416/statm: 8835 7897 326 149 0 8026 0
Current children cumulated CPU time (s) 51.15
Current children cumulated vsize (KiB) 37932

[startup+52.8079 s]
/proc/loadavg: 1.03 1.04 1.01 2/35 28418
/proc/meminfo: memFree=246324/1048576 swapFree=0/0
[pid=28407] ppid=28406 vsize=2592 CPUtime=2.99
/proc/28407/stat : 28407 (aspuncud-user-1) S 28406 28407 22717 34817 22717 4202496 577 23733 0 0 0 0 290 9 15 0 1 0 72478791 2654208 297 1283457024 134512640 135304128 4293855344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28407/statm: 648 297 251 194 0 35 0
[pid=28416] ppid=28407 vsize=35340 CPUtime=49.76
/proc/28416/stat : 28416 (unclasp) R 28407 28407 22717 34817 22717 4202496 425408 0 0 0 4771 205 0 0 25 0 1 0 72478793 36188160 7897 1283457024 134512640 135121179 4288705664 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/28416/statm: 8835 7897 326 149 0 8026 0
Current children cumulated CPU time (s) 52.75
Current children cumulated vsize (KiB) 37932

[startup+53.208 s]
/proc/loadavg: 1.03 1.04 1.01 2/35 28418
/proc/meminfo: memFree=246324/1048576 swapFree=0/0
[pid=28407] ppid=28406 vsize=2592 CPUtime=2.99
/proc/28407/stat : 28407 (aspuncud-user-1) S 28406 28407 22717 34817 22717 4202496 577 23733 0 0 0 0 290 9 15 0 1 0 72478791 2654208 297 1283457024 134512640 135304128 4293855344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28407/statm: 648 297 251 194 0 35 0
[pid=28416] ppid=28407 vsize=35340 CPUtime=50.16
/proc/28416/stat : 28416 (unclasp) R 28407 28407 22717 34817 22717 4202496 428808 0 0 0 4811 205 0 0 25 0 1 0 72478793 36188160 7897 1283457024 134512640 135121179 4288705664 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/28416/statm: 8835 7897 326 149 0 8026 0
Current children cumulated CPU time (s) 53.15
Current children cumulated vsize (KiB) 37932

[startup+53.6082 s]
/proc/loadavg: 1.03 1.04 1.01 2/35 28418
/proc/meminfo: memFree=246324/1048576 swapFree=0/0
[pid=28407] ppid=28406 vsize=2592 CPUtime=2.99
/proc/28407/stat : 28407 (aspuncud-user-1) S 28406 28407 22717 34817 22717 4202496 577 23733 0 0 0 0 290 9 15 0 1 0 72478791 2654208 297 1283457024 134512640 135304128 4293855344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28407/statm: 648 297 251 194 0 35 0
[pid=28416] ppid=28407 vsize=36020 CPUtime=50.57
/proc/28416/stat : 28416 (unclasp) R 28407 28407 22717 34817 22717 4202496 432378 0 0 0 4849 208 0 0 25 0 1 0 72478793 36884480 8067 1283457024 134512640 135121179 4288705664 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/28416/statm: 9005 8067 326 149 0 8196 0
Current children cumulated CPU time (s) 53.56
Current children cumulated vsize (KiB) 38612

[startup+53.7082 s]
/proc/loadavg: 1.03 1.04 1.01 2/35 28418
/proc/meminfo: memFree=246324/1048576 swapFree=0/0
[pid=28407] ppid=28406 vsize=2592 CPUtime=2.99
/proc/28407/stat : 28407 (aspuncud-user-1) S 28406 28407 22717 34817 22717 4202496 577 23733 0 0 0 0 290 9 15 0 1 0 72478791 2654208 297 1283457024 134512640 135304128 4293855344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28407/statm: 648 297 251 194 0 35 0
[pid=28416] ppid=28407 vsize=35340 CPUtime=50.67
/proc/28416/stat : 28416 (unclasp) R 28407 28407 22717 34817 22717 4202496 433058 0 0 0 4859 208 0 0 25 0 1 0 72478793 36188160 7897 1283457024 134512640 135121179 4288705664 18446744073709551615 134690192 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/28416/statm: 8835 7897 326 149 0 8026 0
Current children cumulated CPU time (s) 53.66
Current children cumulated vsize (KiB) 37932

Child status: 0
Real time (s): 53.8007
CPU time (s): 53.7554
CPU user time (s): 51.5632
CPU system time (s): 2.19214
CPU usage (%): 99.9158
Max. virtual memory (cumulated for all children) (KiB): 73508

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 51.5632
system time used= 2.19214
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 460232
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= 1489
involuntary context switches= 1733

runsolver used 0 second user time and 0 second system time

The end