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/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/201108300820/aspuncud-user-1.0/4a69cf16-c731-11df-9182-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.03 1.00 1/36 8650
/proc/meminfo: memFree=937552/1048576 swapFree=0/0
[pid=8650] ppid=8649 vsize=3024 CPUtime=0
/proc/8650/stat : 8650 (runsolver) D 8649 8650 2160 34817 2160 4202560 73 0 0 0 0 0 0 0 25 0 1 0 54272615 3096576 94 1283457024 134512640 134586868 4290081872 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/8650/statm: 756 94 62 19 0 55 0

[startup+0.147126 s]
/proc/loadavg: 1.00 1.03 1.00 1/36 8650
/proc/meminfo: memFree=937552/1048576 swapFree=0/0
[pid=8650] ppid=8649 vsize=2592 CPUtime=0
/proc/8650/stat : 8650 (aspuncud-user-1) S 8649 8650 2160 34817 2160 4202496 573 1518 0 3 0 0 0 0 25 0 1 0 54272615 2654208 298 1283457024 134512640 135304128 4287927056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8650/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.207097 s]
/proc/loadavg: 1.00 1.03 1.00 1/36 8650
/proc/meminfo: memFree=937552/1048576 swapFree=0/0
[pid=8650] ppid=8649 vsize=2592 CPUtime=0
/proc/8650/stat : 8650 (aspuncud-user-1) S 8649 8650 2160 34817 2160 4202496 573 1518 0 3 0 0 0 0 25 0 1 0 54272615 2654208 298 1283457024 134512640 135304128 4287927056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8650/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.308161 s]
/proc/loadavg: 1.00 1.03 1.00 1/36 8650
/proc/meminfo: memFree=937552/1048576 swapFree=0/0
[pid=8650] ppid=8649 vsize=2592 CPUtime=0
/proc/8650/stat : 8650 (aspuncud-user-1) S 8649 8650 2160 34817 2160 4202496 573 1518 0 3 0 0 0 0 25 0 1 0 54272615 2654208 298 1283457024 134512640 135304128 4287927056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8650/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.70825 s]
/proc/loadavg: 1.00 1.03 1.00 1/36 8650
/proc/meminfo: memFree=937552/1048576 swapFree=0/0
[pid=8650] ppid=8649 vsize=2592 CPUtime=0
/proc/8650/stat : 8650 (aspuncud-user-1) S 8649 8650 2160 34817 2160 4202496 573 1518 0 3 0 0 0 0 25 0 1 0 54272615 2654208 298 1283457024 134512640 135304128 4287927056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8650/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.50843 s]
/proc/loadavg: 1.00 1.03 1.00 2/40 8661
/proc/meminfo: memFree=909864/1048576 swapFree=0/0
[pid=8650] ppid=8649 vsize=2592 CPUtime=0
/proc/8650/stat : 8650 (aspuncud-user-1) S 8649 8650 2160 34817 2160 4202496 573 1518 0 3 0 0 0 0 25 0 1 0 54272615 2654208 298 1283457024 134512640 135304128 4287927056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8650/statm: 648 298 251 194 0 35 0
[pid=8659] ppid=8650 vsize=3440 CPUtime=0
/proc/8659/stat : 8659 (unclasp) S 8650 8650 2160 34817 2160 4202496 402 0 5 0 0 0 0 0 25 0 1 0 54272619 3522560 271 1283457024 134512640 135121179 4287709760 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/8659/statm: 860 271 240 149 0 51 0
[pid=8660] ppid=8650 vsize=2692 CPUtime=0
/proc/8660/stat : 8660 (gringo) S 8650 8650 2160 34817 2160 4202496 386 0 23 0 0 0 0 0 24 0 1 0 54272619 2756608 281 1283457024 134512640 137056543 4287123776 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/8660/statm: 673 281 252 622 0 48 0
[pid=8661] ppid=8650 vsize=27968 CPUtime=1.31
/proc/8661/stat : 8661 (cudf2lp) R 8650 8650 2160 34817 2160 4202496 8113 0 15 0 127 4 0 0 25 0 1 0 54272619 28639232 6389 1283457024 134512640 135786343 4287709296 18446744073709551615 135044523 0 0 6 0 0 0 0 17 0 0 0 0
/proc/8661/statm: 6992 6389 128 311 0 6679 0
Current children cumulated CPU time (s) 1.31
Current children cumulated vsize (KiB) 36692

[startup+3.10878 s]
/proc/loadavg: 1.00 1.03 1.00 2/40 8661
/proc/meminfo: memFree=886492/1048576 swapFree=0/0
[pid=8650] ppid=8649 vsize=2592 CPUtime=0
/proc/8650/stat : 8650 (aspuncud-user-1) S 8649 8650 2160 34817 2160 4202496 573 1518 0 3 0 0 0 0 25 0 1 0 54272615 2654208 298 1283457024 134512640 135304128 4287927056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8650/statm: 648 298 251 194 0 35 0
[pid=8659] ppid=8650 vsize=18960 CPUtime=0.08
/proc/8659/stat : 8659 (unclasp) S 8650 8650 2160 34817 2160 4202496 4926 0 6 0 6 2 0 0 18 0 1 0 54272619 19415040 4138 1283457024 134512640 135121179 4287709760 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/8659/statm: 4740 4138 275 149 0 3931 0
[pid=8660] ppid=8650 vsize=28864 CPUtime=0.82
/proc/8660/stat : 8660 (gringo) R 8650 8650 2160 34817 2160 4202496 8324 0 23 0 78 4 0 0 18 0 1 0 54272619 29556736 4925 1283457024 134512640 137056543 4287123776 18446744073709551615 134904717 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8660/statm: 7216 4925 253 622 0 6591 0
[pid=8661] ppid=8650 vsize=40584 CPUtime=1.99
/proc/8661/stat : 8661 (cudf2lp) R 8650 8650 2160 34817 2160 4202496 12846 0 15 0 195 4 0 0 25 0 1 0 54272619 41558016 9951 1283457024 134512640 135786343 4287709296 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/8661/statm: 10146 9951 139 311 0 9833 0
Current children cumulated CPU time (s) 2.89
Current children cumulated vsize (KiB) 91000

[startup+6.30935 s]
/proc/loadavg: 1.08 1.05 1.01 3/39 8661
/proc/meminfo: memFree=832320/1048576 swapFree=0/0
[pid=8650] ppid=8649 vsize=2592 CPUtime=2.51
/proc/8650/stat : 8650 (aspuncud-user-1) S 8649 8650 2160 34817 2160 4202496 573 14367 0 18 0 0 245 6 18 0 1 0 54272615 2654208 298 1283457024 134512640 135304128 4287927056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8650/statm: 648 298 251 194 0 35 0
[pid=8659] ppid=8650 vsize=66332 CPUtime=0.41
/proc/8659/stat : 8659 (unclasp) R 8650 8650 2160 34817 2160 4202496 18626 0 6 0 34 7 0 0 18 0 1 0 54272619 67923968 15667 1283457024 134512640 135121179 4287709760 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8659/statm: 16583 15667 277 149 0 15774 0
[pid=8660] ppid=8650 vsize=93540 CPUtime=3.17
/proc/8660/stat : 8660 (gringo) R 8650 8650 2160 34817 2160 4202496 31168 0 23 0 307 10 0 0 18 0 1 0 54272619 95784960 20131 1283457024 134512640 137056543 4287123776 18446744073709551615 136268342 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8660/statm: 23385 20131 268 622 0 22760 0
Current children cumulated CPU time (s) 6.09
Current children cumulated vsize (KiB) 162464

[startup+12.7112 s]
/proc/loadavg: 1.07 1.04 1.01 2/38 8661
/proc/meminfo: memFree=822548/1048576 swapFree=0/0
[pid=8650] ppid=8649 vsize=2592 CPUtime=6.99
/proc/8650/stat : 8650 (aspuncud-user-1) S 8649 8650 2160 34817 2160 4202496 573 57864 0 41 0 0 674 25 18 0 1 0 54272615 2654208 298 1283457024 134512640 135304128 4287927056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8650/statm: 648 298 251 194 0 35 0
[pid=8659] ppid=8650 vsize=120372 CPUtime=5.5
/proc/8659/stat : 8659 (unclasp) R 8650 8650 2160 34817 2160 4202496 112974 0 7 0 502 48 0 0 25 0 1 0 54272619 123260928 27818 1283457024 134512640 135121179 4287709760 18446744073709551615 134713300 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8659/statm: 30093 27818 319 149 0 29284 0
Current children cumulated CPU time (s) 12.49
Current children cumulated vsize (KiB) 122964

[startup+25.5061 s]
/proc/loadavg: 1.06 1.04 1.00 2/38 8661
/proc/meminfo: memFree=822424/1048576 swapFree=0/0
[pid=8650] ppid=8649 vsize=2592 CPUtime=6.99
/proc/8650/stat : 8650 (aspuncud-user-1) S 8649 8650 2160 34817 2160 4202496 573 57864 0 41 0 0 674 25 18 0 1 0 54272615 2654208 298 1283457024 134512640 135304128 4287927056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8650/statm: 648 298 251 194 0 35 0
[pid=8659] ppid=8650 vsize=120384 CPUtime=18.28
/proc/8659/stat : 8659 (unclasp) R 8650 8650 2160 34817 2160 4202496 365721 0 7 0 1666 162 0 0 25 0 1 0 54272619 123273216 27826 1283457024 134512640 135121179 4287709760 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8659/statm: 30096 27826 319 149 0 29287 0
Current children cumulated CPU time (s) 25.27
Current children cumulated vsize (KiB) 122976

[startup+51.1054 s]
/proc/loadavg: 1.04 1.04 1.00 2/38 8661
/proc/meminfo: memFree=822424/1048576 swapFree=0/0
[pid=8650] ppid=8649 vsize=2592 CPUtime=6.99
/proc/8650/stat : 8650 (aspuncud-user-1) S 8649 8650 2160 34817 2160 4202496 573 57864 0 41 0 0 674 25 18 0 1 0 54272615 2654208 298 1283457024 134512640 135304128 4287927056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8650/statm: 648 298 251 194 0 35 0
[pid=8659] ppid=8650 vsize=120384 CPUtime=43.86
/proc/8659/stat : 8659 (unclasp) R 8650 8650 2160 34817 2160 4202496 862104 0 7 0 4005 381 0 0 25 0 1 0 54272619 123273216 27837 1283457024 134512640 135121179 4287709760 18446744073709551615 134734310 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8659/statm: 30096 27837 321 149 0 29287 0
Current children cumulated CPU time (s) 50.85
Current children cumulated vsize (KiB) 122976

[startup+102.314 s]
/proc/loadavg: 1.01 1.03 1.00 2/38 8661
/proc/meminfo: memFree=822176/1048576 swapFree=0/0
[pid=8650] ppid=8649 vsize=2592 CPUtime=6.99
/proc/8650/stat : 8650 (aspuncud-user-1) S 8649 8650 2160 34817 2160 4202496 573 57864 0 41 0 0 674 25 18 0 1 0 54272615 2654208 298 1283457024 134512640 135304128 4287927056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8650/statm: 648 298 251 194 0 35 0
[pid=8659] ppid=8650 vsize=120388 CPUtime=95.03
/proc/8659/stat : 8659 (unclasp) R 8650 8650 2160 34817 2160 4202496 1851284 0 7 0 8721 782 0 0 25 0 1 0 54272619 123277312 27857 1283457024 134512640 135121179 4287709760 18446744073709551615 134734310 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8659/statm: 30097 27857 321 149 0 29288 0
Current children cumulated CPU time (s) 102.02
Current children cumulated vsize (KiB) 122980

[startup+162.314 s]
/proc/loadavg: 1.00 1.02 1.00 2/38 8661
/proc/meminfo: memFree=821928/1048576 swapFree=0/0
[pid=8650] ppid=8649 vsize=2592 CPUtime=6.99
/proc/8650/stat : 8650 (aspuncud-user-1) S 8649 8650 2160 34817 2160 4202496 573 57864 0 41 0 0 674 25 18 0 1 0 54272615 2654208 298 1283457024 134512640 135304128 4287927056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8650/statm: 648 298 251 194 0 35 0
[pid=8659] ppid=8650 vsize=120404 CPUtime=154.98
/proc/8659/stat : 8659 (unclasp) R 8650 8650 2160 34817 2160 4202496 2980123 0 7 0 14203 1295 0 0 25 0 1 0 54272619 123293696 27881 1283457024 134512640 135121179 4287709760 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8659/statm: 30101 27881 321 149 0 29292 0
Current children cumulated CPU time (s) 161.97
Current children cumulated vsize (KiB) 122996

[startup+222.306 s]
/proc/loadavg: 1.00 1.02 1.00 2/40 8668
/proc/meminfo: memFree=818184/1048576 swapFree=0/0
[pid=8650] ppid=8649 vsize=2592 CPUtime=6.99
/proc/8650/stat : 8650 (aspuncud-user-1) S 8649 8650 2160 34817 2160 4202496 573 57864 0 41 0 0 674 25 18 0 1 0 54272615 2654208 298 1283457024 134512640 135304128 4287927056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8650/statm: 648 298 251 194 0 35 0
[pid=8659] ppid=8650 vsize=124496 CPUtime=214.89
/proc/8659/stat : 8659 (unclasp) R 8650 8650 2160 34817 2160 4202496 4078220 0 7 0 19737 1752 0 0 25 0 1 0 54272619 127483904 28877 1283457024 134512640 135121179 4287709760 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8659/statm: 31124 28877 321 149 0 30315 0
Current children cumulated CPU time (s) 221.88
Current children cumulated vsize (KiB) 127088

[startup+282.306 s]
/proc/loadavg: 1.00 1.01 1.00 2/39 8672
/proc/meminfo: memFree=821548/1048576 swapFree=0/0
[pid=8650] ppid=8649 vsize=2592 CPUtime=6.99
/proc/8650/stat : 8650 (aspuncud-user-1) S 8649 8650 2160 34817 2160 4202496 573 57864 0 41 0 0 674 25 18 0 1 0 54272615 2654208 298 1283457024 134512640 135304128 4287927056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8650/statm: 648 298 251 194 0 35 0
[pid=8659] ppid=8650 vsize=120420 CPUtime=274.83
/proc/8659/stat : 8659 (unclasp) R 8650 8650 2160 34817 2160 4202496 5170850 0 7 0 25264 2219 0 0 25 0 1 0 54272619 123310080 27921 1283457024 134512640 135121179 4287709760 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8659/statm: 30105 27921 321 149 0 29296 0
Current children cumulated CPU time (s) 281.82
Current children cumulated vsize (KiB) 123012



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.509 s]
/proc/loadavg: 1.00 1.01 1.00 2/39 8672
/proc/meminfo: memFree=819068/1048576 swapFree=0/0
[pid=8650] ppid=8649 vsize=2592 CPUtime=6.99
/proc/8650/stat : 8650 (aspuncud-user-1) S 8649 8650 2160 34817 2160 4202496 573 57864 0 41 0 0 674 25 18 0 1 0 54272615 2654208 298 1283457024 134512640 135304128 4287927056 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8650/statm: 648 298 251 194 0 35 0
[pid=8659] ppid=8650 vsize=123288 CPUtime=283.02
/proc/8659/stat : 8659 (unclasp) R 8650 8650 2160 34817 2160 4202496 5317329 0 7 0 26027 2275 0 0 25 0 1 0 54272619 126246912 28639 1283457024 134512640 135121179 4287709760 18446744073709551615 134983096 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8659/statm: 30822 28639 321 149 0 30013 0
Current children cumulated CPU time (s) 290.01
Current children cumulated vsize (KiB) 125880

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.549
CPU time (s): 290.042
CPU user time (s): 267.017
CPU system time (s): 23.0254
CPU usage (%): 99.8254
Max. virtual memory (cumulated for all children) (KiB): 230848

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 267.017
system time used= 23.0254
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 5378165
page faults= 50
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 8516
involuntary context switches= 10382

runsolver used 0 second user time and 0 second system time

The end