nifi-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Alan Jackoway <al...@cloudera.com>
Subject Re: Content Repository Cleanup
Date Thu, 15 Dec 2016 01:56:21 GMT
I agree the limits sound low and will address that tomorrow.

I'm not seeing FileNotFound or NoSuchFile.

Here's an example file:
grep 1481763927251 logs/nifi-app.log
2016-12-14 17:05:27,277 DEBUG [Timer-Driven Process Thread-36]
o.a.n.c.r.c.StandardResourceClaimManager Incrementing claimant count for
StandardResourceClaim[id=1481763927251-1, container=default, section=1] to 1
2016-12-14 17:05:27,357 DEBUG [Timer-Driven Process Thread-2]
o.a.n.c.r.c.StandardResourceClaimManager Incrementing claimant count for
StandardResourceClaim[id=1481763927251-1, container=default, section=1] to 2
2016-12-14 17:05:27,684 DEBUG [Timer-Driven Process Thread-36]
o.a.n.c.r.c.StandardResourceClaimManager Decrementing claimant count for
StandardResourceClaim[id=1481763927251-1, container=default, section=1] to 1
2016-12-14 17:05:27,732 DEBUG [Timer-Driven Process Thread-2]
o.a.n.c.r.c.StandardResourceClaimManager Decrementing claimant count for
StandardResourceClaim[id=1481763927251-1, container=default, section=1] to 0
2016-12-14 17:05:27,909 DEBUG [Timer-Driven Process Thread-14]
o.a.n.c.r.c.StandardResourceClaimManager Incrementing claimant count for
StandardResourceClaim[id=1481763927251-1, container=default, section=1] to 1
2016-12-14 17:05:27,945 DEBUG [Timer-Driven Process Thread-14]
o.a.n.c.r.c.StandardResourceClaimManager Incrementing claimant count for
StandardResourceClaim[id=1481763927251-1, container=default, section=1] to 2
2016-12-14 17:14:26,556 DEBUG [Timer-Driven Process Thread-14]
o.a.n.c.r.c.StandardResourceClaimManager Decrementing claimant count for
StandardResourceClaim[id=1481763927251-1, container=default, section=1] to 1
2016-12-14 17:14:26,556 DEBUG [Timer-Driven Process Thread-14]
o.a.n.c.r.c.StandardResourceClaimManager Decrementing claimant count for
StandardResourceClaim[id=1481763927251-1, container=default, section=1] to 0

This nifi-app.log covers a period when the nifi only handled two sets of
files for a total of maybe 10GB uncompressed. Content repository went over
100GB in that time. I checked a few content repository files, and they all
had similar patterns - claims hit 0 twice - once around 17:05 and once
around 17:14, then nothing. I brought down the nifi around 17:30.

During that time, we did have a processor hitting OutOfMemory while
unpacking a 1GB file. I'm adjusting the heap to try to make that succeed in
case that was related.

On Wed, Dec 14, 2016 at 8:32 PM, Mark Payne <markap14@hotmail.com> wrote:

> 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:ala
> nj@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:m
> arkap14@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:ala
> nj@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