Re: [heka] Idle packs and wedged Heka

[Rob Miller]

I'm not sure exactly what is going on here, but I can provide you w/ some info 
that might help you debug further:

* Any packs that are in a decoder's input channel can only have come from the 
input pool, i.e. inputRecycleChan. I see ~40 packs tied up there.

* Any packs that are in a match channel or input channel for a filter or output 
plugin could have come from either the input pool or the inject pool, although 
they can only have come from the inject pool if they were injected by some 
other filter plugin first. If a plugin's matcher only matches messages that you 
know came directly from an input plugin, then they have to have come from the 
input pool. Most of these are empty, but there are 60 packs sitting in the 
queues for http_metrics_filter.

* Heka doesn't freeze the world while generating the report data, so it's 
possible that the data you're seeing doesn't represent a single point in time, 
which can cause the math to be weird. However, if Heka is truly wedged and no 
traffic is flowing, this is moot, since the state probably isn't changing at 
all during the entire reporting process.

* It's possible for a filter or output to hold an arbitrary number of packs in 
its internal memory. These won't show up in the reporting at all, but neither 
will they be recycled. Without seeing the code that's running in your filters I 
can't say whether or not that's happening.

I have to run into a meeting right now, hopefully this will help at least a 
bit, or at least help you come up with more specific questions.

-r


On 04/04/2016 12:09 PM, Eric LEMOINE wrote:

Hi

We're running into a situation where Heka reports about "idle packs"
and is "wedged". See the Heka diagnostics in
.

So the inject and input recycle channels are empty – no free packs.
And the http_metrics_filter sandbox is blocked in an inject_message()
call waiting for a free inject pack.

We read other threads [*] discussing similar issues, but our case may
be a bit different. The http_metrics_fliter gets messages from
logstreamer inputs, and it injects messages that will be consumed by
the influxdb_accumulator_filter. I think our case is different because
the upstream filter (http_metrics_fliter), as opposed to the
downstream filter (influxdb_accumulator_filter), is blocked. How can
this be possible?

And I really wonder where the inject packs are! The inject recycle
channel is empty, so who holds the inject packs? There are 30 idle
inject packs attributed to the influxdb_accumulator_filter, although
that filter's match channel length is 0 (so is its input channel
length). So I do not understand how this sandbox filter can have idle
packs! And where are the remaining 70 inject packs? Any idea?

In case this is relevant: we use buffering for the output plugins
(with full_action drop), and no buffering for the filters.

This is blocking us big time. Any insight is welcome. Thanks!

[*] 
___
Heka mailing list
Heka@mozilla.org
https://mail.mozilla.org/listinfo/heka



___
Heka mailing list
Heka@mozilla.org
https://mail.mozilla.org/listinfo/heka

Re: [heka] Idle packs and wedged Heka

[Eric LEMOINE]

On Wed, Apr 6, 2016 at 8:48 PM, Rob Miller  wrote:
> I'm not sure exactly what is going on here, but I can provide you w/ some
> info that might help you debug further:
>
> * Any packs that are in a decoder's input channel can only have come from
> the input pool, i.e. inputRecycleChan. I see ~40 packs tied up there.
>
> * Any packs that are in a match channel or input channel for a filter or
> output plugin could have come from either the input pool or the inject pool,
> although they can only have come from the inject pool if they were injected
> by some other filter plugin first. If a plugin's matcher only matches
> messages that you know came directly from an input plugin, then they have to
> have come from the input pool. Most of these are empty, but there are 60
> packs sitting in the queues for http_metrics_filter.
>
> * Heka doesn't freeze the world while generating the report data, so it's
> possible that the data you're seeing doesn't represent a single point in
> time, which can cause the math to be weird. However, if Heka is truly wedged
> and no traffic is flowing, this is moot, since the state probably isn't
> changing at all during the entire reporting process.
>
> * It's possible for a filter or output to hold an arbitrary number of packs
> in its internal memory. These won't show up in the reporting at all, but
> neither will they be recycled. Without seeing the code that's running in
> your filters I can't say whether or not that's happening.
>
> I have to run into a meeting right now, hopefully this will help at least a
> bit, or at least help you come up with more specific questions.


Thanks Rob.

I'll start with one very specific question.

In the diagnostic I have this for the idle inject packs:

2016/03/31 11:56:20 Diagnostics: 30 packs have been idle more than 120 seconds.
2016/03/31 11:56:20 Diagnostics: (inject) Plugin names and quantities
found on idle packs:
2016/03/31 11:56:20 Diagnostics:   influxdb_accumulator_filter: 30

(and no other plugins with idle inject packs!)

In the same diagnostic I have this:

influxdb_accumulator_filter:
InChanCapacity: 30
InChanLength: 0
MatchChanCapacity: 30
MatchChanLength: 0

My question: where can the 30 idle inject packs attributed to
influxdb_accumulator_filter be?

InChanLength is 0, so they're not in the influxdb_accumulator_filter
plugin's input channel. influxdb_accumulator_filter is a sandbox, and
looking at sandbox_filter.go code [*], I do not see how the filter
could be holding these packs.

At some point I thought that these packs could sit in another
filter/output's input channel, or be hold by another filter/channel.
But in that case the diagnostic should attribute the idle inject packs
to that other plugin as well. This is not case, the 30 idle packs are
only attributed to influxdb_accumulator_filter.

[*] 


I hope that my question is clear.

Thanks again!

PS: I hope to come up with more specific information about this problem.
___
Heka mailing list
Heka@mozilla.org
https://mail.mozilla.org/listinfo/heka

Re: [heka] Idle packs and wedged Heka

[Eric LEMOINE]

On Wed, Apr 6, 2016 at 8:48 PM, Rob Miller  wrote:
> I'm not sure exactly what is going on here, but I can provide you w/ some
> info that might help you debug further:
>
> * Any packs that are in a decoder's input channel can only have come from
> the input pool, i.e. inputRecycleChan. I see ~40 packs tied up there.
>
> * Any packs that are in a match channel or input channel for a filter or
> output plugin could have come from either the input pool or the inject pool,
> although they can only have come from the inject pool if they were injected
> by some other filter plugin first. If a plugin's matcher only matches
> messages that you know came directly from an input plugin, then they have to
> have come from the input pool. Most of these are empty, but there are 60
> packs sitting in the queues for http_metrics_filter.
>
> * Heka doesn't freeze the world while generating the report data, so it's
> possible that the data you're seeing doesn't represent a single point in
> time, which can cause the math to be weird. However, if Heka is truly wedged
> and no traffic is flowing, this is moot, since the state probably isn't
> changing at all during the entire reporting process.
>
> * It's possible for a filter or output to hold an arbitrary number of packs
> in its internal memory. These won't show up in the reporting at all, but
> neither will they be recycled. Without seeing the code that's running in
> your filters I can't say whether or not that's happening.
>
> I have to run into a meeting right now, hopefully this will help at least a
> bit, or at least help you come up with more specific questions.


Ok, I have done new tests with fewer plugins. I can reproduce the
"idle packs" issue but the diagnostic makes more sense, matching the
explanation you provided in the old thread (with Bruno Binet).

See 
for the new diagnostic trace.

This time, the downstream filter (influxdb_accumulator_filter) is the
one that is deadlocked. The recycle inject channel is empty, and this
filter has 60 packs in his queues (30 in the match queue and 30 in the
input queue). There are also 30 packs in the router's input queue,
which may be inject packs. So that makes for a maximum of 90 packs.
I'm still missing 10 packs! Any idea where they could be? Note that
the 6 packs in the http_metrics_filter plugin are input packs coming
from keystone_7_0_logstreamer input, they cannot be inject packs
because of the matcher used for that filter.

So I get a diagnostic that makes more sense, but I'm still missing 10
inject packs!

Sorry for insisting. Understanting this would help me troubleshoot
problems in the future.

PS: I am indeed not able to reproduce the problem with poolsize 200,
but I'd like to make sure the problem will not come back in the
future.
___
Heka mailing list
Heka@mozilla.org
https://mail.mozilla.org/listinfo/heka

Re: [heka] Idle packs and wedged Heka

[Rob Miller]

Sorry to be slow to respond, I've been away.

Unfortunately I can't say for sure what's going on here. The idle packs being 
associated w/ your influx accumulator filter appears to imply that the packs 
are being injected into that filter but never recycled. It's possible, however, 
that there's a bug in the diagnostics and that's not accurate. Do you happen to 
be using buffering at all for any of your filter or output plugins?

-r


On 04/08/2016 01:52 PM, Eric LEMOINE wrote:

On Wed, Apr 6, 2016 at 8:48 PM, Rob Miller  wrote:
> I'm not sure exactly what is going on here, but I can provide you w/ some
> info that might help you debug further:
>
> * Any packs that are in a decoder's input channel can only have come from
> the input pool, i.e. inputRecycleChan. I see ~40 packs tied up there.
>
> * Any packs that are in a match channel or input channel for a filter or
> output plugin could have come from either the input pool or the inject pool,
> although they can only have come from the inject pool if they were injected
> by some other filter plugin first. If a plugin's matcher only matches
> messages that you know came directly from an input plugin, then they have to
> have come from the input pool. Most of these are empty, but there are 60
> packs sitting in the queues for http_metrics_filter.
>
> * Heka doesn't freeze the world while generating the report data, so it's
> possible that the data you're seeing doesn't represent a single point in
> time, which can cause the math to be weird. However, if Heka is truly wedged
> and no traffic is flowing, this is moot, since the state probably isn't
> changing at all during the entire reporting process.
>
> * It's possible for a filter or output to hold an arbitrary number of packs
> in its internal memory. These won't show up in the reporting at all, but
> neither will they be recycled. Without seeing the code that's running in
> your filters I can't say whether or not that's happening.
>
> I have to run into a meeting right now, hopefully this will help at least a
> bit, or at least help you come up with more specific questions.


Thanks Rob.

I'll start with one very specific question.

In the diagnostic I have this for the idle inject packs:

2016/03/31 11:56:20 Diagnostics: 30 packs have been idle more than 120 seconds.
2016/03/31 11:56:20 Diagnostics: (inject) Plugin names and quantities
found on idle packs:
2016/03/31 11:56:20 Diagnostics:   influxdb_accumulator_filter: 30

(and no other plugins with idle inject packs!)

In the same diagnostic I have this:

influxdb_accumulator_filter:
 InChanCapacity: 30
 InChanLength: 0
 MatchChanCapacity: 30
 MatchChanLength: 0

My question: where can the 30 idle inject packs attributed to
influxdb_accumulator_filter be?

InChanLength is 0, so they're not in the influxdb_accumulator_filter
plugin's input channel. influxdb_accumulator_filter is a sandbox, and
looking at sandbox_filter.go code [*], I do not see how the filter
could be holding these packs.

At some point I thought that these packs could sit in another
filter/output's input channel, or be hold by another filter/channel.
But in that case the diagnostic should attribute the idle inject packs
to that other plugin as well. This is not case, the 30 idle packs are
only attributed to influxdb_accumulator_filter.

[*] 


I hope that my question is clear.

Thanks again!

PS: I hope to come up with more specific information about this problem.



___
Heka mailing list
Heka@mozilla.org
https://mail.mozilla.org/listinfo/heka

Re: [heka] Idle packs and wedged Heka

[Eric LEMOINE]

Le 14 avr. 2016 19:05, "Rob Miller"  a écrit :
>
> Sorry to be slow to respond, I've been away.
>
> Unfortunately I can't say for sure what's going on here. The idle packs
being associated w/ your influx accumulator filter appears to imply that
the packs are being injected into that filter but never recycled. It's
possible, however, that there's a bug in the diagnostics and that's not
accurate. Do you happen to be using buffering at all for any of your filter
or output plugins?

Buffering is only configured for output plugins.
___
Heka mailing list
Heka@mozilla.org
https://mail.mozilla.org/listinfo/heka