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/201108241238/aspuncud-trendy-1.3/rand83.cudf.dudf-random.log.runsolver ./aspuncud-trendy-1.3 /home/misc2010/data/2011/dudf-random//rand83.cudf /home/misc2010/tmp/201108241238/aspuncud-trendy-1.3/rand83.cudf.dudf-random.result 

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.13 1.10 4/36 24151
/proc/meminfo: memFree=331540/1048576 swapFree=0/0
[pid=24148] ppid=24147 vsize=2588 CPUtime=0
/proc/24148/stat : 24148 (aspuncud-trendy) S 24147 24148 1511 34817 1511 4202496 372 0 0 0 0 0 0 0 25 0 1 0 4715252 2650112 279 1283457024 134512640 135304128 4288896096 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/24148/statm: 647 279 234 194 0 34 0
[pid=24149] ppid=24148 vsize=2588 CPUtime=0
/proc/24149/stat : 24149 (aspuncud-trendy) S 24148 24148 1511 34817 1511 4202560 119 0 0 0 0 0 0 0 25 0 1 0 4715252 2650112 133 1283457024 134512640 135304128 4288896096 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/24149/statm: 647 133 87 194 0 34 0
[pid=24150] ppid=24149 vsize=2588 CPUtime=0
/proc/24150/stat : 24150 (aspuncud-trendy) R 24149 24148 1511 34817 1511 4202560 128 0 0 0 0 0 0 0 25 0 1 0 4715252 2650112 150 1283457024 134512640 135304128 4288896096 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/24150/statm: 647 150 104 194 0 34 0
[pid=24151] ppid=24150 vsize=2588 CPUtime=0
/proc/24151/stat : 24151 (aspuncud-trendy) R 24150 24148 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 4715252 2650112 46 1283457024 134512640 135304128 4288896096 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/24151/statm: 647 46 0 194 0 34 0

[startup+0.178394 s]
/proc/loadavg: 1.25 1.13 1.10 4/36 24151
/proc/meminfo: memFree=331540/1048576 swapFree=0/0
[pid=24148] ppid=24147 vsize=2592 CPUtime=0.02
/proc/24148/stat : 24148 (aspuncud-trendy) S 24147 24148 1511 34817 1511 4202496 622 2231 0 0 0 0 0 2 25 0 1 0 4715252 2654208 297 1283457024 134512640 135304128 4288896096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24148/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2592

[startup+0.212521 s]
/proc/loadavg: 1.25 1.13 1.10 4/36 24151
/proc/meminfo: memFree=331540/1048576 swapFree=0/0
[pid=24148] ppid=24147 vsize=2592 CPUtime=0.02
/proc/24148/stat : 24148 (aspuncud-trendy) S 24147 24148 1511 34817 1511 4202496 622 2231 0 0 0 0 0 2 25 0 1 0 4715252 2654208 297 1283457024 134512640 135304128 4288896096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24148/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2592

[startup+0.302657 s]
/proc/loadavg: 1.25 1.13 1.10 4/36 24151
/proc/meminfo: memFree=331540/1048576 swapFree=0/0
[pid=24148] ppid=24147 vsize=2592 CPUtime=0.02
/proc/24148/stat : 24148 (aspuncud-trendy) S 24147 24148 1511 34817 1511 4202496 622 2231 0 0 0 0 0 2 25 0 1 0 4715252 2654208 297 1283457024 134512640 135304128 4288896096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24148/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2592

[startup+0.706421 s]
/proc/loadavg: 1.25 1.13 1.10 4/36 24151
/proc/meminfo: memFree=331540/1048576 swapFree=0/0
[pid=24148] ppid=24147 vsize=2592 CPUtime=0.02
/proc/24148/stat : 24148 (aspuncud-trendy) S 24147 24148 1511 34817 1511 4202496 622 2231 0 0 0 0 0 2 25 0 1 0 4715252 2654208 297 1283457024 134512640 135304128 4288896096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24148/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2592

[startup+1.50646 s]
/proc/loadavg: 1.23 1.13 1.10 2/37 24162
/proc/meminfo: memFree=294044/1048576 swapFree=0/0
[pid=24148] ppid=24147 vsize=2592 CPUtime=0.02
/proc/24148/stat : 24148 (aspuncud-trendy) S 24147 24148 1511 34817 1511 4202496 622 2231 0 0 0 0 0 2 25 0 1 0 4715252 2654208 297 1283457024 134512640 135304128 4288896096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24148/statm: 648 297 251 194 0 35 0
[pid=24160] ppid=24148 vsize=3444 CPUtime=0
/proc/24160/stat : 24160 (unclasp) S 24148 24148 1511 34817 1511 4202496 406 0 0 0 0 0 0 0 25 0 1 0 4715253 3526656 271 1283457024 134512640 135121179 4294437360 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/24160/statm: 861 271 240 149 0 52 0
[pid=24161] ppid=24148 vsize=2692 CPUtime=0
/proc/24161/stat : 24161 (gringo) S 24148 24148 1511 34817 1511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 4715253 2756608 281 1283457024 134512640 137056543 4289938736 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/24161/statm: 673 281 252 622 0 48 0
[pid=24162] ppid=24148 vsize=25008 CPUtime=1.34
/proc/24162/stat : 24162 (cudf2lp) R 24148 24148 1511 34817 1511 4202496 7187 0 0 0 130 4 0 0 25 0 1 0 4715253 25608192 5595 1283457024 134512640 135786343 4293822816 18446744073709551615 134566250 0 0 6 0 0 0 0 17 0 0 0 0
/proc/24162/statm: 6252 5595 126 311 0 5939 0
Current children cumulated CPU time (s) 1.36
Current children cumulated vsize (KiB) 33736

[startup+3.10885 s]
/proc/loadavg: 1.23 1.13 1.10 2/37 24162
/proc/meminfo: memFree=263628/1048576 swapFree=0/0
[pid=24148] ppid=24147 vsize=2592 CPUtime=2.26
/proc/24148/stat : 24148 (aspuncud-trendy) S 24147 24148 1511 34817 1511 4202496 622 15131 0 0 0 0 216 10 18 0 1 0 4715252 2654208 297 1283457024 134512640 135304128 4288896096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24148/statm: 648 297 251 194 0 35 0
[pid=24160] ppid=24148 vsize=15956 CPUtime=0.08
/proc/24160/stat : 24160 (unclasp) R 24148 24148 1511 34817 1511 4202496 3929 0 0 0 7 1 0 0 18 0 1 0 4715253 16338944 3408 1283457024 134512640 135121179 4294437360 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/24160/statm: 3989 3408 277 149 0 3180 0
[pid=24161] ppid=24148 vsize=21552 CPUtime=0.54
/proc/24161/stat : 24161 (gringo) R 24148 24148 1511 34817 1511 4202496 5853 0 0 0 54 0 0 0 18 0 1 0 4715253 22069248 4165 1283457024 134512640 137056543 4289938736 18446744073709551615 134804084 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/24161/statm: 5388 4165 268 622 0 4763 0
Current children cumulated CPU time (s) 2.88
Current children cumulated vsize (KiB) 40100

[startup+6.31001 s]
/proc/loadavg: 1.21 1.13 1.10 2/35 24162
/proc/meminfo: memFree=276060/1048576 swapFree=0/0
[pid=24148] ppid=24147 vsize=2592 CPUtime=3.07
/proc/24148/stat : 24148 (aspuncud-trendy) S 24147 24148 1511 34817 1511 4202496 622 23877 0 0 0 0 294 13 15 0 1 0 4715252 2654208 297 1283457024 134512640 135304128 4288896096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24148/statm: 648 297 251 194 0 35 0
[pid=24160] ppid=24148 vsize=32684 CPUtime=3.02
/proc/24160/stat : 24160 (unclasp) R 24148 24148 1511 34817 1511 4202496 29143 0 0 0 283 19 0 0 25 0 1 0 4715253 33468416 7268 1283457024 134512640 135121179 4294437360 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/24160/statm: 8171 7268 331 149 0 7362 0
Current children cumulated CPU time (s) 6.09
Current children cumulated vsize (KiB) 35276

[startup+12.7119 s]
/proc/loadavg: 1.19 1.13 1.10 2/35 24162
/proc/meminfo: memFree=275200/1048576 swapFree=0/0
[pid=24148] ppid=24147 vsize=2592 CPUtime=3.07
/proc/24148/stat : 24148 (aspuncud-trendy) S 24147 24148 1511 34817 1511 4202496 622 23877 0 0 0 0 294 13 15 0 1 0 4715252 2654208 297 1283457024 134512640 135304128 4288896096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24148/statm: 648 297 251 194 0 35 0
[pid=24160] ppid=24148 vsize=33708 CPUtime=9.41
/proc/24160/stat : 24160 (unclasp) R 24148 24148 1511 34817 1511 4202496 45071 0 0 0 918 23 0 0 25 0 1 0 4715253 34516992 7525 1283457024 134512640 135121179 4294437360 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/24160/statm: 8427 7525 332 149 0 7618 0
Current children cumulated CPU time (s) 12.48
Current children cumulated vsize (KiB) 36300

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

[startup+12.8119 s]
/proc/loadavg: 1.19 1.13 1.10 2/35 24162
/proc/meminfo: memFree=275200/1048576 swapFree=0/0
[pid=24148] ppid=24147 vsize=2592 CPUtime=3.07
/proc/24148/stat : 24148 (aspuncud-trendy) S 24147 24148 1511 34817 1511 4202496 622 23877 0 0 0 0 294 13 15 0 1 0 4715252 2654208 297 1283457024 134512640 135304128 4288896096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24148/statm: 648 297 251 194 0 35 0
[pid=24160] ppid=24148 vsize=33708 CPUtime=9.51
/proc/24160/stat : 24160 (unclasp) R 24148 24148 1511 34817 1511 4202496 45071 0 0 0 928 23 0 0 25 0 1 0 4715253 34516992 7525 1283457024 134512640 135121179 4294437360 18446744073709551615 134734446 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/24160/statm: 8427 7525 332 149 0 7618 0
Current children cumulated CPU time (s) 12.58
Current children cumulated vsize (KiB) 36300

[startup+13.6122 s]
/proc/loadavg: 1.19 1.13 1.10 2/35 24162
/proc/meminfo: memFree=274828/1048576 swapFree=0/0
[pid=24148] ppid=24147 vsize=2592 CPUtime=3.07
/proc/24148/stat : 24148 (aspuncud-trendy) S 24147 24148 1511 34817 1511 4202496 622 23877 0 0 0 0 294 13 15 0 1 0 4715252 2654208 297 1283457024 134512640 135304128 4288896096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24148/statm: 648 297 251 194 0 35 0
[pid=24160] ppid=24148 vsize=33324 CPUtime=10.31
/proc/24160/stat : 24160 (unclasp) R 24148 24148 1511 34817 1511 4202496 49187 0 0 0 1006 25 0 0 25 0 1 0 4715253 34123776 7429 1283457024 134512640 135121179 4294437360 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/24160/statm: 8331 7429 332 149 0 7522 0
Current children cumulated CPU time (s) 13.38
Current children cumulated vsize (KiB) 35916

[startup+13.8122 s]
/proc/loadavg: 1.19 1.13 1.10 2/35 24162
/proc/meminfo: memFree=274828/1048576 swapFree=0/0
[pid=24148] ppid=24147 vsize=2592 CPUtime=3.07
/proc/24148/stat : 24148 (aspuncud-trendy) S 24147 24148 1511 34817 1511 4202496 622 23877 0 0 0 0 294 13 15 0 1 0 4715252 2654208 297 1283457024 134512640 135304128 4288896096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24148/statm: 648 297 251 194 0 35 0
[pid=24160] ppid=24148 vsize=32976 CPUtime=10.51
/proc/24160/stat : 24160 (unclasp) R 24148 24148 1511 34817 1511 4202496 50838 0 0 0 1025 26 0 0 25 0 1 0 4715253 33767424 7342 1283457024 134512640 135121179 4294437360 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/24160/statm: 8244 7342 332 149 0 7435 0
Current children cumulated CPU time (s) 13.58
Current children cumulated vsize (KiB) 35568

[startup+13.9123 s]
/proc/loadavg: 1.19 1.13 1.10 2/35 24162
/proc/meminfo: memFree=274828/1048576 swapFree=0/0
[pid=24148] ppid=24147 vsize=2592 CPUtime=3.07
/proc/24148/stat : 24148 (aspuncud-trendy) S 24147 24148 1511 34817 1511 4202496 622 23877 0 0 0 0 294 13 15 0 1 0 4715252 2654208 297 1283457024 134512640 135304128 4288896096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24148/statm: 648 297 251 194 0 35 0
[pid=24160] ppid=24148 vsize=32164 CPUtime=10.61
/proc/24160/stat : 24160 (unclasp) R 24148 24148 1511 34817 1511 4202496 51677 0 0 0 1034 27 0 0 25 0 1 0 4715253 32935936 7215 1283457024 134512640 135121179 4294437360 18446744073709551615 4158420435 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/24160/statm: 8041 7215 342 149 0 7232 0
Current children cumulated CPU time (s) 13.68
Current children cumulated vsize (KiB) 34756

Child status: 0
Real time (s): 13.9484
CPU time (s): 13.7289
CPU user time (s): 13.3168
CPU system time (s): 0.412025
CPU usage (%): 98.4257
Max. virtual memory (cumulated for all children) (KiB): 73004

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 13.3168
system time used= 0.412025
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 78801
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= 1534
involuntary context switches= 1361

runsolver used 0 second user time and 0 second system time

The end