AbstractFeedGenerator warning

[dullaertd]

hello,

I have a freshly deployed alfresco 3.0.1 running on Weblogic, that was installed on solaris. For the backend we use Oracle 10g2

When I look in the log files, i keep getting the same warning (shown below). Could some one tell me what this means and perhaps how to resolve it?

10:43:12,912 WARN  [org.alfresco.repo.activities.feed.AbstractFeedGenerator] Still busy …
10:51:42,905 WARN  [org.alfresco.repo.activities.feed.AbstractFeedGenerator] Still busy …
11:04:42,917 WARN  [org.alfresco.repo.activities.feed.AbstractFeedGenerator] Still busy …
11:09:42,913 WARN  [org.alfresco.repo.activities.feed.AbstractFeedGenerator] Still busy …
11:13:12,920 WARN  [org.alfresco.repo.activities.feed.AbstractFeedGenerator] Still busy …
11:13:42,920 WARN  [org.alfresco.repo.activities.feed.AbstractFeedGenerator] Still busy …
11:14:12,920 WARN  [org.alfresco.repo.activities.feed.AbstractFeedGenerator] Still busy …
11:24:42,921 WARN  [org.alfresco.repo.activities.feed.AbstractFeedGenerator] Still busy …
11:43:12,908 WARN  [org.alfresco.repo.activities.feed.AbstractFeedGenerator] Still busy …
11:43:42,908 WARN  [org.alfresco.repo.activities.feed.AbstractFeedGenerator] Still busy …
11:44:12,907 WARN  [org.alfresco.repo.activities.feed.AbstractFeedGenerator] Still busy …
12:05:12,910 WARN  [org.alfresco.repo.activities.feed.AbstractFeedGenerator] Still busy …
12:05:47,215 WARN  [org.alfresco.repo.activities.feed.AbstractFeedGenerator] Still busy …
12:06:12,919 WARN  [org.alfresco.repo.activities.feed.AbstractFeedGenerator] Still busy …



Thanx in Advance!

[svast]

Looks like the quartz jobs are blocked somehow…

FYI: Luis Alves reported a JIRA issue about it
http://issues.alfresco.com/jira/browse/ALF-4020?page=com.atlassian.streams.streams-jira-plugin%3Aact...

[janv]

This warning message is mostly likely to be a symptom rather than the underlying cause, which could be exhausted DB connections. Disabling the feed generator may simply shift the symptom elsewhere.

For this particular warning message the FeedGenerator job (used to generate Share Activity Feeds) could be hanging when simply trying to query the DB, even if the activity tables are empty. Hence the next iteration of the FeedGenerator job will see that the previous iteration has not yet completed (even if there is no work to do) and issue the warning.

Please double-check your DB configuration to ensure it is configured appropriately for the expected level of concurrency / load. For example:

- for Alfresco you may need to increase the "db.pool.max" which is currently set to 40 by default
- it is also important to check (and if necessary, reconfigure) your DB server to handle at least 10 more connections than the total number of pool connections expected … taking into account all client/node pools that access the DB server (which may included multiple Alfresco nodes in a clustered setup)

In a dev/test environment, you can also check for leaked DB connections by custom overriding the "defaultDataSource" bean and adding the following property:

       <property name="logAbandoned" >
            <value>true</value>
        </property>

Hope this helps.

[svast]

@janv: All right, thank you very much for the tip. Increasing db.pool.max did help a little.

I can read in https://issues.alfresco.com/jira/browse/ALF-4020 that you just set the issue at "won't fix".
Can you explain why this won't be fixed?

I don't understand the benefit of 'Hiding the issue by leveraging the logging level' as a solution.
Is it the warning message that causes the application to dead-lock ?  meaning that no warn message may lead to no deadlock?

[janv]

>> @janv: All right, thank you very much for the tip. Increasing db.pool.max did help a little.

What do you mean by "help a little" ?

>> Can you explain why this won't be fixed?

"Won't fix" simply means that we will leave the warning message as-is for the time being (rather than remove or hide it).

>> Is it the warning message that causes the application to dead-lock ?

The warning message does not cause the deadlock. As per earlier post, it appears to be a symptom (not the underlying cause). It simply indicates that the previous execution of the activities feed generator job is still busy for some reason. That particular job runs regularly (by default, every 30 secs) hence might already be busy processing a large number of Share activities *or* waiting for a DB connection (even if the queries will be against an empty "alf_activity_post" table). The latter seems to be the case here. You can confirm this (ie. empty table) by temporarily adding the following debug:

log4j.logger.org.alfresco.repo.activities.feed.local.LocalFeedGenerator=debug
‍‍‍

If you're not causing Share activities to be posted (hence the table is empty) then you will see debug approx every 30 secs, such as:

15:58:25,611  DEBUG [feed.local.LocalFeedGenerator] >>> No work to be done for this job cycle: local
15:58:55,609  DEBUG [feed.local.LocalFeedGenerator] >>> No work to be done for this job cycle: local
15:59:25,610  DEBUG [feed.local.LocalFeedGenerator] >>> No work to be done for this job cycle: local
15:59:55,609  DEBUG [feed.local.LocalFeedGenerator] >>> No work to be done for this job cycle: local
‍‍‍‍‍‍

If you *also* still see the warning message intermittently:

11:13:12,920 WARN [org.alfresco.repo.activities.feed.AbstractFeedGenerator] Still busy …
‍‍‍

then it implies that it (ie. previous job iteration) is still waiting to get a DB connection.

If you hide the warning message or even explicitly disable the activities feed generator job then it is still possible that other threads could hang due to an exhausted DB connection pool.

Regards,
Jan

[svast]

>> @janv: All right, thank you very much for the tip. Increasing db.pool.max did help a little.

What do you mean by "help a little" ?

I mean that I don't have that message as often as before. I've just realized the db.pool.max was not high enough.
Now it works flawlessly, with db.pool.max=350

>> Is it the warning message that causes the application to dead-lock ?

The warning message does not cause the deadlock. As per earlier post, it appears to be a symptom (not the underlying cause). It simply indicates that the previous execution of the activities feed generator job is still busy for some reason. That particular job runs regularly (by default, every 30 secs) hence might already be busy processing a large number of Share activities *or* waiting for a DB connection (even if the queries will be against an empty "alf_activity_post" table). The latter seems to be the case here. You can confirm this (ie. empty table) by temporarily adding the following debug:

If you're not causing Share activities to be posted (hence the table is empty) then you will see debug approx every 30 secs, such as:

I don't use Share at all, so my guess is the table will remain empty.

If you hide the warning message or even explicitly disable the activities feed generator job then it is still possible that other threads could hang due to an exhausted DB connection pool.

Regards,
Jan

Now I understand much better the whole picture, thank you for the time spent.

[svast]

So after digging a while about that "Still busy…" issue, I saw that it was supposed to be fixed in v3.4a onwards.
But it seems to be back again as http://issues.alfresco.com/jira/browse/ALF-5837

I can confirm the issue is still here when using Alfresco v3.4.c, unfortunately.