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/rand408.cudf.s-e-l.log.runsolver ./aspuncud-trendy-1.3 /home/misc2010/data/2011/incremental/s-e-l/rand408.cudf /home/misc2010/tmp/201108241238/aspuncud-trendy-1.3/rand408.cudf.s-e-l.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.00 1.02 1.00 4/37 11787
/proc/meminfo: memFree=540512/1048576 swapFree=0/0
[pid=11785] ppid=11784 vsize=2588 CPUtime=0
/proc/11785/stat : 11785 (aspuncud-trendy) S 11784 11785 1511 34817 1511 4202496 374 0 0 0 0 0 0 0 18 0 1 0 2777499 2650112 280 1283457024 134512640 135304128 4292575200 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/11785/statm: 647 280 234 194 0 34 0
[pid=11786] ppid=11785 vsize=2588 CPUtime=0
/proc/11786/stat : 11786 (aspuncud-trendy) S 11785 11785 1511 34817 1511 4202560 118 0 0 0 0 0 0 0 18 0 1 0 2777499 2650112 134 1283457024 134512640 135304128 4292575200 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/11786/statm: 647 134 87 194 0 34 0
[pid=11787] ppid=11786 vsize=2588 CPUtime=0.01
/proc/11787/stat : 11787 (aspuncud-trendy) R 11786 11785 1511 34817 1511 4202560 99 0 0 0 0 1 0 0 25 0 1 0 2777499 2650112 124 1283457024 134512640 135304128 4292575200 18446744073709551615 134694904 0 0 0 65538 0 0 0 17 0 0 0 0
/proc/11787/statm: 647 124 77 194 0 34 0

[startup+0.118542 s]
/proc/loadavg: 1.00 1.02 1.00 4/37 11787
/proc/meminfo: memFree=540512/1048576 swapFree=0/0
[pid=11785] ppid=11784 vsize=2592 CPUtime=0.01
/proc/11785/stat : 11785 (aspuncud-trendy) S 11784 11785 1511 34817 1511 4202496 618 2231 0 0 0 0 0 1 25 0 1 0 2777499 2654208 298 1283457024 134512640 135304128 4292575200 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11785/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.206637 s]
/proc/loadavg: 1.00 1.02 1.00 4/37 11787
/proc/meminfo: memFree=540512/1048576 swapFree=0/0
[pid=11785] ppid=11784 vsize=2592 CPUtime=0.01
/proc/11785/stat : 11785 (aspuncud-trendy) S 11784 11785 1511 34817 1511 4202496 618 2231 0 0 0 0 0 1 25 0 1 0 2777499 2654208 298 1283457024 134512640 135304128 4292575200 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11785/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.306555 s]
/proc/loadavg: 1.00 1.02 1.00 4/37 11787
/proc/meminfo: memFree=540512/1048576 swapFree=0/0
[pid=11785] ppid=11784 vsize=2592 CPUtime=0.01
/proc/11785/stat : 11785 (aspuncud-trendy) S 11784 11785 1511 34817 1511 4202496 618 2231 0 0 0 0 0 1 25 0 1 0 2777499 2654208 298 1283457024 134512640 135304128 4292575200 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11785/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.7066 s]
/proc/loadavg: 1.00 1.02 1.00 4/37 11787
/proc/meminfo: memFree=540512/1048576 swapFree=0/0
[pid=11785] ppid=11784 vsize=2592 CPUtime=0.01
/proc/11785/stat : 11785 (aspuncud-trendy) S 11784 11785 1511 34817 1511 4202496 618 2231 0 0 0 0 0 1 25 0 1 0 2777499 2654208 298 1283457024 134512640 135304128 4292575200 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11785/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+1.50461 s]
/proc/loadavg: 1.00 1.02 1.00 2/39 11800
/proc/meminfo: memFree=498104/1048576 swapFree=0/0
[pid=11785] ppid=11784 vsize=2592 CPUtime=0.01
/proc/11785/stat : 11785 (aspuncud-trendy) S 11784 11785 1511 34817 1511 4202496 618 2231 0 0 0 0 0 1 25 0 1 0 2777499 2654208 298 1283457024 134512640 135304128 4292575200 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11785/statm: 648 298 251 194 0 35 0
[pid=11797] ppid=11785 vsize=7488 CPUtime=0
/proc/11797/stat : 11797 (unclasp) S 11785 11785 1511 34817 1511 4202496 1521 0 0 0 0 0 0 0 18 0 1 0 2777501 7667712 1304 1283457024 134512640 135121179 4287398704 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/11797/statm: 1872 1304 275 149 0 1063 0
[pid=11798] ppid=11785 vsize=8672 CPUtime=0.19
/proc/11798/stat : 11798 (gringo) S 11785 11785 1511 34817 1511 4202496 2250 0 0 0 19 0 0 0 18 0 1 0 2777501 8880128 1445 1283457024 134512640 137056543 4289442992 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/11798/statm: 2168 1445 253 622 0 1543 0
[pid=11799] ppid=11785 vsize=30576 CPUtime=1.17
/proc/11799/stat : 11799 (cudf2lp) R 11785 11785 1511 34817 1511 4202496 10049 0 0 0 113 4 0 0 25 0 1 0 2777501 31309824 7426 1283457024 134512640 135786343 4290266624 18446744073709551615 134815749 0 0 6 0 0 0 0 17 0 0 0 0
/proc/11799/statm: 7644 7426 137 311 0 7331 0
Current children cumulated CPU time (s) 1.37
Current children cumulated vsize (KiB) 49328

[startup+3.10493 s]
/proc/loadavg: 1.00 1.01 1.00 3/38 11800
/proc/meminfo: memFree=493284/1048576 swapFree=0/0
[pid=11785] ppid=11784 vsize=2592 CPUtime=2.09
/proc/11785/stat : 11785 (aspuncud-trendy) S 11784 11785 1511 34817 1511 4202496 618 20372 0 0 0 0 199 10 16 0 1 0 2777499 2654208 298 1283457024 134512640 135304128 4292575200 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11785/statm: 648 298 251 194 0 35 0
[pid=11797] ppid=11785 vsize=30112 CPUtime=0.88
/proc/11797/stat : 11797 (unclasp) R 11785 11785 1511 34817 1511 4202496 11157 0 0 0 86 2 0 0 19 0 1 0 2777501 30834688 6646 1283457024 134512640 135121179 4287398704 18446744073709551615 4157441437 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11797/statm: 7528 6646 327 149 0 6719 0
Current children cumulated CPU time (s) 2.97
Current children cumulated vsize (KiB) 32704

[startup+6.30579 s]
/proc/loadavg: 1.00 1.01 1.00 2/37 11800
/proc/meminfo: memFree=500864/1048576 swapFree=0/0
[pid=11785] ppid=11784 vsize=2592 CPUtime=2.09
/proc/11785/stat : 11785 (aspuncud-trendy) S 11784 11785 1511 34817 1511 4202496 618 20372 0 0 0 0 199 10 16 0 1 0 2777499 2654208 298 1283457024 134512640 135304128 4292575200 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11785/statm: 648 298 251 194 0 35 0
[pid=11797] ppid=11785 vsize=31356 CPUtime=4.08
/proc/11797/stat : 11797 (unclasp) R 11785 11785 1511 34817 1511 4202496 35321 0 0 0 388 20 0 0 25 0 1 0 2777501 32108544 6914 1283457024 134512640 135121179 4287398704 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11797/statm: 7839 6914 333 149 0 7030 0
Current children cumulated CPU time (s) 6.17
Current children cumulated vsize (KiB) 33948

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

[startup+6.40582 s]
/proc/loadavg: 1.00 1.01 1.00 2/37 11800
/proc/meminfo: memFree=500864/1048576 swapFree=0/0
[pid=11785] ppid=11784 vsize=2592 CPUtime=2.09
/proc/11785/stat : 11785 (aspuncud-trendy) S 11784 11785 1511 34817 1511 4202496 618 20372 0 0 0 0 199 10 16 0 1 0 2777499 2654208 298 1283457024 134512640 135304128 4292575200 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11785/statm: 648 298 251 194 0 35 0
[pid=11797] ppid=11785 vsize=31356 CPUtime=4.18
/proc/11797/stat : 11797 (unclasp) R 11785 11785 1511 34817 1511 4202496 35321 0 0 0 398 20 0 0 25 0 1 0 2777501 32108544 6914 1283457024 134512640 135121179 4287398704 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11797/statm: 7839 6914 333 149 0 7030 0
Current children cumulated CPU time (s) 6.27
Current children cumulated vsize (KiB) 33948

[startup+6.80598 s]
/proc/loadavg: 1.00 1.01 1.00 2/37 11800
/proc/meminfo: memFree=500368/1048576 swapFree=0/0
[pid=11785] ppid=11784 vsize=2592 CPUtime=2.09
/proc/11785/stat : 11785 (aspuncud-trendy) S 11784 11785 1511 34817 1511 4202496 618 20372 0 0 0 0 199 10 16 0 1 0 2777499 2654208 298 1283457024 134512640 135304128 4292575200 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11785/statm: 648 298 251 194 0 35 0
[pid=11797] ppid=11785 vsize=31336 CPUtime=4.58
/proc/11797/stat : 11797 (unclasp) R 11785 11785 1511 34817 1511 4202496 37576 0 0 0 436 22 0 0 25 0 1 0 2777501 32088064 6873 1283457024 134512640 135121179 4287398704 18446744073709551615 134992064 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11797/statm: 7834 6873 333 149 0 7025 0
Current children cumulated CPU time (s) 6.67
Current children cumulated vsize (KiB) 33928

[startup+7.00606 s]
/proc/loadavg: 1.00 1.01 1.00 2/37 11800
/proc/meminfo: memFree=500368/1048576 swapFree=0/0
[pid=11785] ppid=11784 vsize=2592 CPUtime=2.09
/proc/11785/stat : 11785 (aspuncud-trendy) S 11784 11785 1511 34817 1511 4202496 618 20372 0 0 0 0 199 10 16 0 1 0 2777499 2654208 298 1283457024 134512640 135304128 4292575200 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11785/statm: 648 298 251 194 0 35 0
[pid=11797] ppid=11785 vsize=30756 CPUtime=4.78
/proc/11797/stat : 11797 (unclasp) R 11785 11785 1511 34817 1511 4202496 39191 0 0 0 455 23 0 0 25 0 1 0 2777501 31494144 6764 1283457024 134512640 135121179 4287398704 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11797/statm: 7689 6764 333 149 0 6880 0
Current children cumulated CPU time (s) 6.87
Current children cumulated vsize (KiB) 33348

[startup+7.10609 s]
/proc/loadavg: 1.00 1.01 1.00 2/37 11800
/proc/meminfo: memFree=500368/1048576 swapFree=0/0
[pid=11785] ppid=11784 vsize=2592 CPUtime=2.09
/proc/11785/stat : 11785 (aspuncud-trendy) S 11784 11785 1511 34817 1511 4202496 618 20372 0 0 0 0 199 10 16 0 1 0 2777499 2654208 298 1283457024 134512640 135304128 4292575200 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11785/statm: 648 298 251 194 0 35 0
[pid=11797] ppid=11785 vsize=30756 CPUtime=4.88
/proc/11797/stat : 11797 (unclasp) R 11785 11785 1511 34817 1511 4202496 40061 0 0 0 465 23 0 0 25 0 1 0 2777501 31494144 6764 1283457024 134512640 135121179 4287398704 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11797/statm: 7689 6764 333 149 0 6880 0
Current children cumulated CPU time (s) 6.97
Current children cumulated vsize (KiB) 33348

Child status: 0
Real time (s): 7.19052
CPU time (s): 7.06844
CPU user time (s): 6.70042
CPU system time (s): 0.368023
CPU usage (%): 98.3023
Max. virtual memory (cumulated for all children) (KiB): 60540

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 6.70042
system time used= 0.368023
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 63833
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= 1236
involuntary context switches= 987

runsolver used 0 second user time and 0 second system time

The end