nifi-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Mark Payne <marka...@hotmail.com>
Subject Re: Content Repository Cleanup
Date Thu, 15 Dec 2016 01:32:46 GMT
OK, so these are generally the default values for most linux systems. These are a little low,
though for what NiFi recommends and often needs. With these settings, you can easily run
out of open file handles. When this happens, trying to access a file will return a FileNotFoundException
even though the file exists and permissions all look good. As a result, NiFi may be failing
to
delete the data simply because it can't get an open file handle.

The admin guide [1] explains the best practices for configuring these settings. Generally,
after updating
these settings, I think you have to logout of the machine and login again for the changes
to take effect.
Would recommend you update these settings and also search logs for "FileNotFound" as well
as
"NoSuchFile" and see if that hits anywhere.


[1] http://nifi.apache.org/docs/nifi-docs/html/administration-guide.html#configuration-best-practices


On Dec 14, 2016, at 8:25 PM, Alan Jackoway <alanj@cloudera.com<mailto:alanj@cloudera.com>>
wrote:

We haven't let the disk hit 100% in a while, but it's been crossing 90%. We
haven't seen the "Unable to checkpoint" message in the last 24 hours.

$ ulimit -Hn
4096
$ ulimit -Sn
1024

I will work on tracking a specific file next.


On Wed, Dec 14, 2016 at 8:17 PM, Alan Jackoway <alanj@cloudera.com<mailto:alanj@cloudera.com>>
wrote:

At first I thought that the drained messages always said 0, but that's not
right. What should the total number of claims drained be? The number of
flowfiles that made it through the system? If so, I think our number is low:

$ grep "StandardResourceClaimManager Drained" nifi-app_2016-12-14*  | grep
-v "Drained 0" | awk '{sum += $9} END {print sum}'
25296

I'm not sure how to get the count of flowfiles that moved through, but I
suspect that's low by an order of magnitude. That instance of nifi has
handled 150k files in the last 6 hours, most of which went through a number
of processors and transformations.

Should the number of drained claims correspond to the number of flow files
that moved through the system?
Alan

On Wed, Dec 14, 2016 at 6:59 PM, Alan Jackoway <alanj@cloudera.com<mailto:alanj@cloudera.com>>
wrote:

Some updates:
* We fixed the issue with missing transfer relationships, and this did
not go away.
* We saw this a few minutes ago when the queue was at 0.

What should I be looking for in the logs to figure out the issue?

Thanks,
Alan

On Mon, Dec 12, 2016 at 12:45 PM, Alan Jackoway <alanj@cloudera.com<mailto:alanj@cloudera.com>>
wrote:

In case this is interesting, I think this started getting bad when we
started hitting an error where some of our files were not given a transfer
relationship. Maybe some combination of not giving flow files a
relationship and the subsequent penalization is causing the problem.

On Mon, Dec 12, 2016 at 12:16 PM, Alan Jackoway <alanj@cloudera.com<mailto:alanj@cloudera.com>>
wrote:

Everything is at the default locations for these nifis.

On one of the two machines, I did find log messages like you suggested:
2016-12-11 08:00:59,389 ERROR [pool-10-thread-1]
o.a.n.c.r.WriteAheadFlowFileRepository Unable to checkpoint FlowFile
Repository due to java.io.FileNotFoundException:
./flowfile_repository/partition-14/3169.journal (No space left on
device)

I added the logger, which apparently takes effect right away. What am I
looking for in this logs? I see a lot of stuff like:
2016-12-12 07:19:03,560 DEBUG [Timer-Driven Process Thread-24]
o.a.n.c.r.c.StandardResourceClaimManager Decrementing claimant count
for StandardResourceClaim[id=1481555893660-3174, container=default,
section=102] to 0
2016-12-12 07:19:03,561 DEBUG [Timer-Driven Process Thread-31]
o.a.n.c.r.c.StandardResourceClaimManager Decrementing claimant count
for StandardResourceClaim[id=1481555922818-3275, container=default,
section=203] to 191
2016-12-12 07:19:03,605 DEBUG [Timer-Driven Process Thread-8]
o.a.n.c.r.c.StandardResourceClaimManager Decrementing claimant count
for StandardResourceClaim[id=1481555880393-3151, container=default,
section=79] to 142
2016-12-12 07:19:03,624 DEBUG [Timer-Driven Process Thread-38]
o.a.n.c.r.c.StandardResourceClaimManager Decrementing claimant count
for StandardResourceClaim[id=1481555872053-3146, container=default,
section=74] to 441
2016-12-12 07:19:03,625 DEBUG [Timer-Driven Process Thread-25]
o.a.n.c.r.c.StandardResourceClaimManager Decrementing claimant count
for StandardResourceClaim[id=1481555893954-3178, container=default,
section=106] to 2
2016-12-12 07:19:03,647 DEBUG [Timer-Driven Process Thread-24]
o.a.n.c.r.c.StandardResourceClaimManager Decrementing claimant count
for StandardResourceClaim[id=1481555893696-3175, container=default,
section=103] to 1
2016-12-12 07:19:03,705 DEBUG [FileSystemRepository Workers Thread-1]
o.a.n.c.r.c.StandardResourceClaimManager Drained 0 destructable claims
to []

What's puzzling to me is that both of these machines have > 100GB of
free space, and I have never seen the queued size go above 20GB. It seems
to me like it gets into a state where nothing is deleted long before it
runs out of disk space.

Thanks,
Alan

On Mon, Dec 12, 2016 at 9:13 AM, Mark Payne <markap14@hotmail.com<mailto:markap14@hotmail.com>>
wrote:

Alan,

Thanks for the thread-dump and the in-depth analysis!

So in terms of the two tasks there, here's a quick explanation of what
each does:
ArchiveOrDestroyDestructableClaims - When a Resource Claim (which
maps to a file on disk) is no longer referenced
by any FlowFile, it can be either archived or destroyed (depending on
whether the property in nifi.properties has archiving
enabled).
DestroyExpiredArchiveClaims - When archiving is enabled, the Resource
Claims that are archived have to eventually
age off. This task is responsible for ensuring that this happens.

As you mentioned, in the Executor, if the Runnable fails it will stop
running forever, and if the thread gets stuck, another will
not be launched. Neither of these appears to be the case. I say this
because both of those Runnables are wrapped entirely
within a try { ... } catch (Throwable t) {...}. So the method will
never end Exceptionally. Also, the thread dump shows all of the
threads created by that Thread Pool (those whose names begin with
"FileSystemRepository Workers Thread-") in WAITING
or TIMED_WAITING state. This means that they are sitting in the
Executor waiting to be scheduled to do something else,
so they aren't stuck in any kind of infinite loop or anything like
that.

Now, with all of that being said, I have a theory as to what could
perhaps be happening :)

>From the configuration that you listed below, it shows that the
content repository is located at ./content_repository, which is
the default. Is the FlowFile Repository also located at the default
location of ./flowfile_repository? The reason that I ask is this:

When I said above that a Resource Claim is marked destructible when no
more FlowFiles reference it, that was a bit of a
simplification. A more detailed explanation is this: when the FlowFile
Repository is checkpointed (this happens every 2 minutes
by default), its Write-Ahead Log is "rolled over" (or "checkpointed"
or "compacted" or however you like to refer to it). When this
happens, we do an fsync() to ensure that the data is stored safely on
disk. Only then do we actually mark a claim as destructible.
This is done in order to ensure that if there is a power outage and a
FlowFile Repository update wasn't completely flushed to disk,
that we can recover. For instance, if the content of a FlowFile
changes from Resource Claim A to Resource Claim B and as a result
we delete Resource Claim A and then lose power, it's possible that the
FlowFile Repository didn't flush that update to disk; as a result,
on restart, we may still have that FlowFile pointing to Resource Claim
A which is now deleted, so we would end up having data loss.
This method of only deleting Resource Claims after the FlowFile
Repository has been fsync'ed means that we know on restart that
Resource Claim A won't still be referenced.

So that was probably a very wordy, verbose description of what happens
but I'm trying to make sure that I explain things adequately.
So with that background... if you are storing your FlowFile Repository
on the same volume as your Content Repository, the following
could happen:

At some point in time, enough data is queued up in your flow for you
to run out of disk space. As a result, the FlowFile Repository is
unable to be compacted. Since this is not happening, it will not mark
any of the Resource Claims as destructible. This would mean that
the Content Repository does not get cleaned up. So now you've got a
full Content Repository and it's unable to clean up after itself, because
no Resource Claims are getting marked as destructible.

So to prove or disprove this theory, there are a few things that you
can look at:

Do you see the following anywhere in your logs: Unable to checkpoint
FlowFile Repository

If you add the following to your conf/logback.xml:
<logger name="org.apache.nifi.controller.repository.claim.StandardResourceClaimManager"
level="DEBUG" />
Then that should allow you to see a DEBUG-level log message every time
that a Resource Claim is marked destructible and every time
that the Content Repository requests the collection of Destructible
Claims ("Drained 100 destructable claims" for instance)

Any of the logs related to those statements should be very valuable in
determining what's going on.

Thanks again for all of the detailed analysis. Hopefully we can get
this all squared away and taken care of quickly!

-Mark


On Dec 11, 2016, at 1:21 PM, Alan Jackoway <alanj@cloudera.com<mailto:alanj@cloudera.com><mailto:
alanj@cloudera.com<mailto:alanj@cloudera.com>>> wrote:

Here is what I have figured out so far.

The cleanups are scheduled at https://github.com/apache/nifi
/blob/master/nifi-nar-bundles/nifi-framework-bundle/nifi-fra
mework/nifi-framework-core/src/main/java/org/apache/nifi/con
troller/repository/FileSystemRepository.java#L232

I'm not totally sure which one of those is the one that should be
cleaning things up. It's either ArchiveOrDestroyDestructableClaims or
DestroyExpiredArchiveClaims, both of which are in that class, and both of
which are scheduled with scheduleWithFixedDelay. Based on docs at
https://docs.oracle.com/javase/7/docs/api/java/util/concurre
nt/ScheduledThreadPoolExecutor.html#scheduleWithFixedDelay(j
ava.lang.Runnable,%20long,%20long,%20java.util.concurrent.TimeUnit)
if those methods fail once, they will stop running forever. Also if the
thread got stuck it wouldn't launch a new one.

I then hoped I would go into the logs, see a failure, and use it to
figure out the issue.

What I'm seeing instead is things like this, which comes from
BinDestructableClaims:
2016-12-10 23:08:50,117 INFO [Cleanup Archive for default]
o.a.n.c.repository.FileSystemRepository Deleted 159 files from
archive for Container default; oldest Archive Date is now Sat Dec 10
22:09:53 PST 2016; container cleanup took 34266 millis
that are somewhat frequent (as often as once per second, which is the
scheduling frequency). Then, eventually, they just stop. Unfortunately
there isn't an error message I can find that's killing these.

At nifi startup, I see messages like this, which come from something
(not sure what yet) calling the cleanup() method on FileSystemRepository:
2016-12-11 09:15:38,973 INFO [main] o.a.n.c.repository.FileSystemRepository
Found unknown file /home/cops/edh-bundle-extracto
r/content_repository/0/1481467667784-2048 (1749645 bytes) in File
System Repository; removing file
I never see those after the initial cleanup that happens on restart.

I attached a thread dump. I noticed at the top that there is a cleanup
thread parked. I took 10 more thread dumps after this and in every one of
them the cleanup thread was parked. That thread looks like it corresponds
to DestroyExpiredArchiveClaims, so I think it's incidental. I believe that
if the cleanup task I need were running, it would be in one of the
FileSystemRepository Workers. However, in all of my thread dumps, these
were always all parked.

Attached one of the thread dumps.

Thanks,
Alan


On Sun, Dec 11, 2016 at 12:17 PM, Mark Payne <markap14@hotmail.com
<mailto:markap14@hotmail.com>> wrote:
Alan,


It's possible that you've run into some sort of bug that is preventing

it from cleaning up the Content  Repository properly. While it's stuck

in this state, could you capture a thread dump (bin/nifi.sh dump
thread-dump.txt)?

That would help us determine if there is something going on that is

preventing the cleanup from happening.


Thanks

-Mark


________________________________
From: Alan Jackoway <alanj@cloudera.com<mailto:alanj@cloudera.com>>
Sent: Sunday, December 11, 2016 11:11 AM
To: dev@nifi.apache.org<mailto:dev@nifi.apache.org>
Subject: Re: Content Repository Cleanup

This just filled up again even
with nifi.content.repository.archive.enabled=false.

On the node that is still alive, our queued flowfiles are 91 / 16.47
GB,
but the content repository directory is using 646 GB.

Is there a property I can set to make it clean things up more
frequently? I
expected that once I turned archive enabled off, it would delete things
from the content repository as soon as the flow files weren't queued
anywhere. So far the only way I have found to reliably get nifi to
clear
out the content repository is to restart it.

Our version string is the following, if that interests you:
11/26/2016 04:39:37 PST
Tagged nifi-1.1.0-RC2
>From ${buildRevision} on branch ${buildBranch}

Maybe we will go to the released 1.1 and see if that helps. Until then
I'll
be restarting a lot and digging into the code to figure out where this
cleanup is supposed to happen. Any pointers on code/configs for that
would
be appreciated.

Thanks,
Alan

On Sun, Dec 11, 2016 at 8:51 AM, Joe Gresock <jgresock@gmail.com
<mailto:jgresock@gmail.com>> wrote:

No, in my scenario a server restart would not affect the content
repository
size.

On Sun, Dec 11, 2016 at 8:46 AM, Alan Jackoway <alanj@cloudera.com
<mailto:alanj@cloudera.com>> wrote:

If we were in the situation Joe G described, should we expect that
when
we
kill and restart nifi it would clean everything up? That behavior
has
been
consistent every time - when the disk hits 100%, we kill nifi,
delete
enough old content files to bring it back up, and before it bring
the UI
up
it deletes things to get within the archive policy again. That
sounds
less
like the files are stuck and more like it failed trying.

For now I just turned off archiving, since we don't really need it
for
this use case.

I attached a jstack from last night's failure, which looks pretty
boring
to me.

On Sun, Dec 11, 2016 at 1:37 AM, Alan Jackoway <alanj@cloudera.com
<mailto:alanj@cloudera.com>>
wrote:

The scenario Joe G describes is almost exactly what we are doing.
We
bring in large files and unpack them into many smaller ones. In
the most
recent iteration of this problem, I saw that we had many small
files
queued
up at the time trouble was happening. We will try your suggestion
to
see if
the situation improves.

Thanks,
Alan

On Sat, Dec 10, 2016 at 6:57 AM, Joe Gresock <jgresock@gmail.com
<mailto:jgresock@gmail.com>>
wrote:

Not sure if your scenario is related, but one of the NiFi devs
recently
explained to me that the files in the content repository are
actually
appended together with other flow file content (please correct
me if
I'm
explaining it wrong).  That means if you have many small flow
files in
your
current backlog, and several large flow files have recently left
the
flow,
the large ones could still be hanging around in the content
repository
as
long as the small ones are still there, if they're in the same
appended
files on disk.

This scenario recently happened to us: we had a flow with ~20
million
tiny
flow files queued up, and at the same time we were also
processing a
bunch
of 1GB files, which left the flow quickly.  The content
repository was
much
larger than what was actually being reported in the flow stats,
and our
disks were almost full.  On a hunch, I tried the following
strategy:
- MergeContent the tiny flow files using flow-file-v3 format (to
capture
all attributes)
- MergeContent 10,000 of the packaged flow files using tar
format for
easier storage on disk
- PutFile into a directory
- GetFile from the same directory, but using back pressure from
here on
out
(so that the flow simply wouldn't pull the same files from disk
until
it
was really ready for them)
- UnpackContent (untar them)
- UnpackContent (turn them back into flow files with the original
attributes)
- Then do the processing they were originally designed for

This had the effect of very quickly reducing the size of my
content
repository to very nearly the actual size I saw reported in the
flow,
and
my disk usage dropped from ~95% to 50%, which is the configured
content
repository max usage percentage.  I haven't had any problems
since.

Hope this helps.
Joe

On Sat, Dec 10, 2016 at 12:04 AM, Joe Witt <joe.witt@gmail.com
<mailto:joe.witt@gmail.com>> wrote:

Alan,

That retention percentage only has to do with the archive of
data
which kicks in once a given chunk of content is no longer
reachable
by
active flowfiles in the flow.  For it to grow to 100%
typically would
mean that you have data backlogged in the flow that account
for that
much space.  If that is certainly not the case for you then we
need
to
dig deeper.  If you could do screenshots or share log files
and stack
dumps around this time those would all be helpful.  If the
screenshots
and such are too sensitive please just share as much as you
can.

Thanks
Joe

On Fri, Dec 9, 2016 at 9:55 PM, Alan Jackoway <
alanj@cloudera.com<mailto:alanj@cloudera.com>>
wrote:
One other note on this, when it came back up there were tons
of
messages
like this:

2016-12-09 18:36:36,244 INFO [main] o.a.n.c.repository.
FileSystemRepository
Found unknown file /path/to/content_repository/49
8/1481329796415-87538
(1071114 bytes) in File System Repository; archiving file

I haven't dug into what that means.
Alan

On Fri, Dec 9, 2016 at 9:53 PM, Alan Jackoway <
alanj@cloudera.com<mailto:alanj@cloudera.com>>
wrote:

Hello,

We have a node on which nifi content repository keeps
growing to
use
100%
of the disk. It's a relatively high-volume process. It
chewed
through
more
than 100GB in the three hours between when we first saw it
hit
100%
of
the
disk and when we just cleaned it up again.

We are running nifi 1.1 for this. Our nifi.properties
looked like
this:

nifi.content.repository.implementation=org.apache.
nifi.controller.repository.FileSystemRepository
nifi.content.claim.max.appendable.size=10 MB
nifi.content.claim.max.flow.files=100
nifi.content.repository.direct
ory.default=./content_repository
nifi.content.repository.archive.max.retention.period=12
hours
nifi.content.repository.archive.max.usage.percentage=50%
nifi.content.repository.archive.enabled=true
nifi.content.repository.always.sync=false

I just bumped retention period down to 2 hours, but should
max
usage
percentage protect us from using 100% of the disk?

Unfortunately we didn't get jstacks on either failure. If
it hits
100%
again I will make sure to get that.

Thanks,
Alan





--
I know what it is to be in need, and I know what it is to have
plenty.  I
have learned the secret of being content in any and every
situation,
whether well fed or hungry, whether living in plenty or in
want.  I can
do
all this through him who gives me strength.    *-Philippians
4:12-13*






--
I know what it is to be in need, and I know what it is to have
plenty.  I
have learned the secret of being content in any and every situation,
whether well fed or hungry, whether living in plenty or in want.  I
can do
all this through him who gives me strength.    *-Philippians 4:12-13*


<thread-dump.txt>








Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message