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/201108300820/aspuncud-user-1.0/ca8f656c-db9e-11df-b9cf-00163e3d3b7c.cudf.dudf-real.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-real//ca8f656c-db9e-11df-b9cf-00163e3d3b7c.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/ca8f656c-db9e-11df-b9cf-00163e3d3b7c.cudf.dudf-real.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.00 1.01 1.00 1/35 15428
/proc/meminfo: memFree=949212/1048576 swapFree=0/0
[pid=15428] ppid=15427 vsize=3020 CPUtime=0
/proc/15428/stat : 15428 (runsolver) D 15427 15428 2160 34817 2160 4202560 72 0 0 0 0 0 0 0 25 0 1 0 57945035 3092480 94 1283457024 134512640 134586868 4287463888 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/15428/statm: 755 94 62 19 0 54 0

[startup+0.406043 s]
/proc/loadavg: 1.00 1.01 1.00 1/35 15428
/proc/meminfo: memFree=949212/1048576 swapFree=0/0
[pid=15428] ppid=15427 vsize=2592 CPUtime=0
/proc/15428/stat : 15428 (aspuncud-user-1) S 15427 15428 2160 34817 2160 4202496 567 1518 0 3 0 0 0 0 25 0 1 0 57945035 2654208 297 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15428/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.505967 s]
/proc/loadavg: 1.00 1.01 1.00 1/35 15428
/proc/meminfo: memFree=949212/1048576 swapFree=0/0
[pid=15428] ppid=15427 vsize=2592 CPUtime=0
/proc/15428/stat : 15428 (aspuncud-user-1) S 15427 15428 2160 34817 2160 4202496 567 1518 0 3 0 0 0 0 25 0 1 0 57945035 2654208 297 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15428/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.605999 s]
/proc/loadavg: 1.00 1.01 1.00 1/35 15428
/proc/meminfo: memFree=949212/1048576 swapFree=0/0
[pid=15428] ppid=15427 vsize=2592 CPUtime=0
/proc/15428/stat : 15428 (aspuncud-user-1) S 15427 15428 2160 34817 2160 4202496 567 1518 0 3 0 0 0 0 25 0 1 0 57945035 2654208 297 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15428/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.706013 s]
/proc/loadavg: 1.00 1.01 1.00 1/35 15428
/proc/meminfo: memFree=949212/1048576 swapFree=0/0
[pid=15428] ppid=15427 vsize=2592 CPUtime=0
/proc/15428/stat : 15428 (aspuncud-user-1) S 15427 15428 2160 34817 2160 4202496 567 1518 0 3 0 0 0 0 25 0 1 0 57945035 2654208 297 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15428/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.50616 s]
/proc/loadavg: 1.00 1.01 1.00 2/39 15439
/proc/meminfo: memFree=913952/1048576 swapFree=0/0
[pid=15428] ppid=15427 vsize=2592 CPUtime=0
/proc/15428/stat : 15428 (aspuncud-user-1) S 15427 15428 2160 34817 2160 4202496 567 1518 0 3 0 0 0 0 25 0 1 0 57945035 2654208 297 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15428/statm: 648 297 251 194 0 35 0
[pid=15437] ppid=15428 vsize=6800 CPUtime=0.02
/proc/15437/stat : 15437 (unclasp) S 15428 15428 2160 34817 2160 4202496 1286 0 6 0 2 0 0 0 18 0 1 0 57945040 6963200 1157 1283457024 134512640 135121179 4294856048 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/15437/statm: 1700 1157 275 149 0 891 0
[pid=15438] ppid=15428 vsize=7304 CPUtime=0.14
/proc/15438/stat : 15438 (gringo) R 15428 15428 2160 34817 2160 4202496 1789 0 22 0 14 0 0 0 18 0 1 0 57945040 7479296 1311 1283457024 134512640 137056543 4288742416 18446744073709551615 136301696 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15438/statm: 1826 1311 253 622 0 1201 0
[pid=15439] ppid=15428 vsize=27588 CPUtime=1.18
/proc/15439/stat : 15439 (cudf2lp) R 15428 15428 2160 34817 2160 4202496 8918 0 15 0 112 6 0 0 25 0 1 0 57945040 28250112 6666 1283457024 134512640 135786343 4292857968 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/15439/statm: 6897 6666 139 311 0 6584 0
Current children cumulated CPU time (s) 1.34
Current children cumulated vsize (KiB) 44284

[startup+3.1065 s]
/proc/loadavg: 1.00 1.01 1.00 3/39 15439
/proc/meminfo: memFree=880348/1048576 swapFree=0/0
[pid=15428] ppid=15427 vsize=2592 CPUtime=0
/proc/15428/stat : 15428 (aspuncud-user-1) S 15427 15428 2160 34817 2160 4202496 567 1518 0 3 0 0 0 0 25 0 1 0 57945035 2654208 297 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15428/statm: 648 297 251 194 0 35 0
[pid=15437] ppid=15428 vsize=28236 CPUtime=0.12
/proc/15437/stat : 15437 (unclasp) S 15428 15428 2160 34817 2160 4202496 7630 0 6 0 8 4 0 0 18 0 1 0 57945040 28913664 6437 1283457024 134512640 135121179 4294856048 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/15437/statm: 7059 6437 275 149 0 6250 0
[pid=15438] ppid=15428 vsize=40928 CPUtime=1.39
/proc/15438/stat : 15438 (gringo) S 15428 15428 2160 34817 2160 4202496 12492 0 22 0 130 9 0 0 18 0 1 0 57945040 41910272 7778 1283457024 134512640 137056543 4288742416 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/15438/statm: 10232 7778 253 622 0 9607 0
[pid=15439] ppid=15428 vsize=27588 CPUtime=1.41
/proc/15439/stat : 15439 (cudf2lp) R 15428 15428 2160 34817 2160 4202496 8918 0 15 0 133 8 0 0 25 0 1 0 57945040 28250112 6666 1283457024 134512640 135786343 4292857968 18446744073709551615 134524997 0 0 6 0 0 0 0 17 0 0 0 0
/proc/15439/statm: 6897 6666 139 311 0 6584 0
Current children cumulated CPU time (s) 2.92
Current children cumulated vsize (KiB) 99344

[startup+6.30757 s]
/proc/loadavg: 1.00 1.01 1.00 2/37 15440
/proc/meminfo: memFree=886776/1048576 swapFree=0/0
[pid=15428] ppid=15427 vsize=2592 CPUtime=3.96
/proc/15428/stat : 15428 (aspuncud-user-1) S 15427 15428 2160 34817 2160 4202496 567 37609 0 40 0 0 368 28 18 0 1 0 57945035 2654208 297 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15428/statm: 648 297 251 194 0 35 0
[pid=15437] ppid=15428 vsize=63904 CPUtime=2.16
/proc/15437/stat : 15437 (unclasp) R 15428 15428 2160 34817 2160 4202496 35745 0 7 0 198 18 0 0 20 0 1 0 57945040 65437696 14709 1283457024 134512640 135121179 4294856048 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15437/statm: 15976 14709 319 149 0 15167 0
Current children cumulated CPU time (s) 6.12
Current children cumulated vsize (KiB) 66496

[startup+12.7096 s]
/proc/loadavg: 1.00 1.01 1.00 2/37 15440
/proc/meminfo: memFree=886156/1048576 swapFree=0/0
[pid=15428] ppid=15427 vsize=2592 CPUtime=3.96
/proc/15428/stat : 15428 (aspuncud-user-1) S 15427 15428 2160 34817 2160 4202496 567 37609 0 40 0 0 368 28 18 0 1 0 57945035 2654208 297 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15428/statm: 648 297 251 194 0 35 0
[pid=15437] ppid=15428 vsize=64404 CPUtime=8.55
/proc/15437/stat : 15437 (unclasp) R 15428 15428 2160 34817 2160 4202496 116937 0 7 0 800 55 0 0 25 0 1 0 57945040 65949696 14839 1283457024 134512640 135121179 4294856048 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15437/statm: 16101 14839 319 149 0 15292 0
Current children cumulated CPU time (s) 12.51
Current children cumulated vsize (KiB) 66996

[startup+25.5103 s]
/proc/loadavg: 1.00 1.01 1.00 2/37 15441
/proc/meminfo: memFree=884544/1048576 swapFree=0/0
[pid=15428] ppid=15427 vsize=2592 CPUtime=3.96
/proc/15428/stat : 15428 (aspuncud-user-1) S 15427 15428 2160 34817 2160 4202496 567 37609 0 40 0 0 368 28 18 0 1 0 57945035 2654208 297 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15428/statm: 648 297 251 194 0 35 0
[pid=15437] ppid=15428 vsize=67220 CPUtime=21.32
/proc/15437/stat : 15437 (unclasp) R 15428 15428 2160 34817 2160 4202496 266156 0 7 0 2004 128 0 0 25 0 1 0 57945040 68833280 15612 1283457024 134512640 135121179 4294856048 18446744073709551615 134981267 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15437/statm: 16805 15612 321 149 0 15996 0
Current children cumulated CPU time (s) 25.28
Current children cumulated vsize (KiB) 69812

[startup+51.1133 s]
/proc/loadavg: 1.00 1.01 1.00 2/36 15443
/proc/meminfo: memFree=886048/1048576 swapFree=0/0
[pid=15428] ppid=15427 vsize=2592 CPUtime=3.96
/proc/15428/stat : 15428 (aspuncud-user-1) S 15427 15428 2160 34817 2160 4202496 567 37609 0 40 0 0 368 28 18 0 1 0 57945035 2654208 297 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15428/statm: 648 297 251 194 0 35 0
[pid=15437] ppid=15428 vsize=64924 CPUtime=46.89
/proc/15437/stat : 15437 (unclasp) R 15428 15428 2160 34817 2160 4202496 558247 0 7 0 4439 250 0 0 25 0 1 0 57945040 66482176 15005 1283457024 134512640 135121179 4294856048 18446744073709551615 134734361 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15437/statm: 16231 15005 321 149 0 15422 0
Current children cumulated CPU time (s) 50.85
Current children cumulated vsize (KiB) 67516

[startup+102.314 s]
/proc/loadavg: 1.00 1.00 1.00 2/36 15443
/proc/meminfo: memFree=886296/1048576 swapFree=0/0
[pid=15428] ppid=15427 vsize=2592 CPUtime=3.96
/proc/15428/stat : 15428 (aspuncud-user-1) S 15427 15428 2160 34817 2160 4202496 567 37609 0 40 0 0 368 28 18 0 1 0 57945035 2654208 297 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15428/statm: 648 297 251 194 0 35 0
[pid=15437] ppid=15428 vsize=65568 CPUtime=98
/proc/15437/stat : 15437 (unclasp) R 15428 15428 2160 34817 2160 4202496 1204176 0 7 0 9272 528 0 0 25 0 1 0 57945040 67141632 15174 1283457024 134512640 135121179 4294856048 18446744073709551615 134990512 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15437/statm: 16392 15174 321 149 0 15583 0
Current children cumulated CPU time (s) 101.96
Current children cumulated vsize (KiB) 68160

[startup+162.302 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 15443
/proc/meminfo: memFree=885808/1048576 swapFree=0/0
[pid=15428] ppid=15427 vsize=2592 CPUtime=3.96
/proc/15428/stat : 15428 (aspuncud-user-1) S 15427 15428 2160 34817 2160 4202496 567 37609 0 40 0 0 368 28 18 0 1 0 57945035 2654208 297 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15428/statm: 648 297 251 194 0 35 0
[pid=15437] ppid=15428 vsize=64040 CPUtime=157.84
/proc/15437/stat : 15437 (unclasp) R 15428 15428 2160 34817 2160 4202496 1967080 0 7 0 14923 861 0 0 25 0 1 0 57945040 65576960 14847 1283457024 134512640 135121179 4294856048 18446744073709551615 134891399 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15437/statm: 16010 14847 321 149 0 15201 0
Current children cumulated CPU time (s) 161.8
Current children cumulated vsize (KiB) 66632

[startup+222.303 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 15443
/proc/meminfo: memFree=885436/1048576 swapFree=0/0
[pid=15428] ppid=15427 vsize=2592 CPUtime=3.96
/proc/15428/stat : 15428 (aspuncud-user-1) S 15427 15428 2160 34817 2160 4202496 567 37609 0 40 0 0 368 28 18 0 1 0 57945035 2654208 297 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15428/statm: 648 297 251 194 0 35 0
[pid=15437] ppid=15428 vsize=64312 CPUtime=217.73
/proc/15437/stat : 15437 (unclasp) R 15428 15428 2160 34817 2160 4202496 2719921 0 7 0 20598 1175 0 0 25 0 1 0 57945040 65855488 14940 1283457024 134512640 135121179 4294856048 18446744073709551615 4159931475 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15437/statm: 16078 14940 321 149 0 15269 0
Current children cumulated CPU time (s) 221.69
Current children cumulated vsize (KiB) 66904

[startup+282.306 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 15443
/proc/meminfo: memFree=880724/1048576 swapFree=0/0
[pid=15428] ppid=15427 vsize=2592 CPUtime=3.96
/proc/15428/stat : 15428 (aspuncud-user-1) S 15427 15428 2160 34817 2160 4202496 567 37609 0 40 0 0 368 28 18 0 1 0 57945035 2654208 297 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15428/statm: 648 297 251 194 0 35 0
[pid=15437] ppid=15428 vsize=70876 CPUtime=277.59
/proc/15437/stat : 15437 (unclasp) R 15428 15428 2160 34817 2160 4202496 3481382 0 7 0 26235 1524 0 0 25 0 1 0 57945040 72577024 16555 1283457024 134512640 135121179 4294856048 18446744073709551615 4158397206 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15437/statm: 17719 16555 323 149 0 16910 0
Current children cumulated CPU time (s) 281.55
Current children cumulated vsize (KiB) 73468



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.809 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 15443
/proc/meminfo: memFree=877748/1048576 swapFree=0/0
[pid=15428] ppid=15427 vsize=2592 CPUtime=3.96
/proc/15428/stat : 15428 (aspuncud-user-1) S 15427 15428 2160 34817 2160 4202496 567 37609 0 40 0 0 368 28 18 0 1 0 57945035 2654208 297 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15428/statm: 648 297 251 194 0 35 0
[pid=15437] ppid=15428 vsize=71420 CPUtime=286.06
/proc/15437/stat : 15437 (unclasp) R 15428 15428 2160 34817 2160 4202496 3586847 0 7 0 27044 1562 0 0 25 0 1 0 57945040 73134080 16784 1283457024 134512640 135121179 4294856048 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15437/statm: 17855 16784 323 149 0 17046 0
Current children cumulated CPU time (s) 290.02
Current children cumulated vsize (KiB) 74012

Sending User defined signal 1 to process tree (bottom up)
Sleeping 10 seconds

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

Child status: 0
Real time (s): 290.854
CPU time (s): 290.058
CPU user time (s): 274.141
CPU system time (s): 15.917
CPU usage (%): 99.7262
Max. virtual memory (cumulated for all children) (KiB): 149180

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 274.141
system time used= 15.917
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 3627399
page faults= 49
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 4282
involuntary context switches= 6819

runsolver used 0.004 second user time and 0 second system time

The end