Thread list - more info

[Steve Fatula]

So, here are the relevant logging entries:

2010-02-01 11:01:12,762 (TP-Processor26) [ ServiceDispatcher.java:
599:INFO ] [[ASync service started...- total:0.0,since last(Begin):
0.0]] - 'store / sendOrderConfirmation'
2010-02-01 11:01:12,767 (TP-Processor26) [ GenericAsyncEngine.java:
137:INFO ] Persisted job queued : 1265050872766
2010-02-01 11:01:12,768 (TP-Processor26) [ ServiceDispatcher.java:
696:INFO ] [[ASync service finished...- total:0.006,since last(ASync  
service sta...):0.006]] - 'store / sendOrderConfirmation'
2010-02-01 11:01:31,174 (default-invoker-Thread-980027)  
[ JobInvoker.java:231:INFO ] Invoker [default-invoker-Thread-980027]  
received job [1265050872766] from poller  
[org.ofbiz.service.job.JobPoller@6aadae91]
2010-02-01 11:01:31,176 (default-invoker-Thread-980027)  
[PersistedServiceJob.java:176:INFO ]  
org.ofbiz.service.job.PersistedServiceJob@4ed9bcaa[72203] -- Next  
runtime: Wed Dec 31 15:59:59 PST 1969
2010-02-01 11:01:31,195 (default-invoker-Thread-980027)  
[ WicketURLEncoder.java:203:WARN ] No current Application found -  
defaulting encoding to UTF-8
2010-02-01 11:01:31,195 (default-invoker-Thread-980027)  
[ WicketURLEncoder.java:203:WARN ] No current Application found -  
defaulting encoding to UTF-8
2010-02-01 11:01:31,239 (default-invoker-Thread-980027)  
[ServiceEcaCondition.java:155:WARN ] From Field (communicationEventId)  
is not found in context for sendMail, defaulting to null.
2010-02-01 11:01:31,240 (default-invoker-Thread-980027)  
[ ServiceEcaRule.java:133:INFO ] For Service ECA [sendMail] on  
[commit] got false for condition: [partyId][equals][1][true][String]
2010-02-01 11:01:31,241 (default-invoker-Thread-980027)  
[ ServiceDispatcher.java:578:INFO ] Sync service [JobDispatcher/
sendMailFromScreen] finished in [57] milliseconds
2010-02-01 11:01:31,241 (default-invoker-Thread-980027)  
[ ServiceEcaRule.java:150:INFO ] Running Service ECA Service:  
createOrderNotificationLog, triggered by rule on Service:  
sendOrderConfirmation
2010-02-01 11:01:31,244 (default-invoker-Thread-980027)  
[ ServiceDispatcher.java:578:INFO ] Sync service [JobDispatcher/
sendOrderConfirmation] finished in [64] milliseconds

Note it says the service finished, yet, it is still marked as running  
in the webtools thread list. Those seem to never go away, eventually,  
I presume we will run out of available threads.

Where can I look to help debug this further? I looked back and this  
did not happen on the old machine, the jobs were always marked as  
finished.

Email was in fact sent, to me and I got it, so, it did run.

[Adrian Crum]

Threads and jobs are not the same thing. What is it that you are trying
to debug?

-Adrian

Steve wrote:

> So, here are the relevant logging entries:
>
> 2010-02-01 11:01:12,762 (TP-Processor26) [
> ServiceDispatcher.java:599:INFO ] [[ASync service started...-
> total:0.0,since last(Begin):0.0]] - 'store / sendOrderConfirmation'
> 2010-02-01 11:01:12,767 (TP-Processor26) [
> GenericAsyncEngine.java:137:INFO ] Persisted job queued : 1265050872766
> 2010-02-01 11:01:12,768 (TP-Processor26) [
> ServiceDispatcher.java:696:INFO ] [[ASync service finished...-
> total:0.006,since last(ASync service sta...):0.006]] - 'store /
> sendOrderConfirmation'
> 2010-02-01 11:01:31,174 (default-invoker-Thread-980027) [
> JobInvoker.java:231:INFO ] Invoker [default-invoker-Thread-980027]
> received job [1265050872766] from poller
> [org.ofbiz.service.job.JobPoller@6aadae91]
> 2010-02-01 11:01:31,176 (default-invoker-Thread-980027)
> [PersistedServiceJob.java:176:INFO ]
> org.ofbiz.service.job.PersistedServiceJob@4ed9bcaa[72203] -- Next
> runtime: Wed Dec 31 15:59:59 PST 1969
> 2010-02-01 11:01:31,195 (default-invoker-Thread-980027) [
> WicketURLEncoder.java:203:WARN ] No current Application found -
> defaulting encoding to UTF-8
> 2010-02-01 11:01:31,195 (default-invoker-Thread-980027) [
> WicketURLEncoder.java:203:WARN ] No current Application found -
> defaulting encoding to UTF-8
> 2010-02-01 11:01:31,239 (default-invoker-Thread-980027)
> [ServiceEcaCondition.java:155:WARN ] From Field (communicationEventId)
> is not found in context for sendMail, defaulting to null.
> 2010-02-01 11:01:31,240 (default-invoker-Thread-980027) [
> ServiceEcaRule.java:133:INFO ] For Service ECA [sendMail] on [commit]
> got false for condition: [partyId][equals][1][true][String]
> 2010-02-01 11:01:31,241 (default-invoker-Thread-980027) [
> ServiceDispatcher.java:578:INFO ] Sync service
> [JobDispatcher/sendMailFromScreen] finished in [57] milliseconds
> 2010-02-01 11:01:31,241 (default-invoker-Thread-980027) [
> ServiceEcaRule.java:150:INFO ] Running Service ECA Service:
> createOrderNotificationLog, triggered by rule on Service:
> sendOrderConfirmation
> 2010-02-01 11:01:31,244 (default-invoker-Thread-980027) [
> ServiceDispatcher.java:578:INFO ] Sync service
> [JobDispatcher/sendOrderConfirmation] finished in [64] milliseconds
>
> Note it says the service finished, yet, it is still marked as running in
> the webtools thread list. Those seem to never go away, eventually, I
> presume we will run out of available threads.
>
> Where can I look to help debug this further? I looked back and this did
> not happen on the old machine, the jobs were always marked as finished.
>
> Email was in fact sent, to me and I got it, so, it did run.
>

[Steve Fatula]

What I am trying to debug is the fact that the thread list accumulates  
(in the service engine threads section) async services that are  
running, and, the threads never go back to status sleeping.

The thread list lists the service engine threads that are running on  
top. Those jobs are async services in this case like  
sendOrderConfirmation

If you look in the job list, you can see the service that is listed in  
the thread list, and the status is running, just like the thread list  
shows.

So, the issue is async services are never marked as SERVICE_FINISHED,  
they stay at SERVICE_RUNNING

The log below shows it completed, and I did receive the email.

2010-02-01 11:01:12,762 (TP-Processor26) [ ServiceDispatcher.java:
599:INFO ] [[ASync service started...- total:0.0,since last(Begin):
0.0]] - 'neobits / sendOrderConfirmation'
2010-02-01 11:01:12,767 (TP-Processor26) [ GenericAsyncEngine.java:
137:INFO ] Persisted job queued : 1265050872766
2010-02-01 11:01:12,768 (TP-Processor26) [ ServiceDispatcher.java:
696:INFO ] [[ASync service finished...- total:0.006,since last(ASync  
service sta...):0.006]] - 'neobits / sendOrderConfirmation'
2010-02-01 11:01:31,174 (default-invoker-Thread-980027)  
[ JobInvoker.java:231:INFO ] Invoker [default-invoker-Thread-980027]  
received job [1265050872766] from poller  
[org.ofbiz.service.job.JobPoller@6aadae91]
2010-02-01 11:01:31,176 (default-invoker-Thread-980027)  
[PersistedServiceJob.java:176:INFO ]  
org.ofbiz.service.job.PersistedServiceJob@4ed9bcaa[72203] -- Next  
runtime: Wed Dec 31 15:59:59 PST 1969
2010-02-01 11:01:31,195 (default-invoker-Thread-980027)  
[ WicketURLEncoder.java:203:WARN ] No current Application found -  
defaulting encoding to UTF-8
2010-02-01 11:01:31,195 (default-invoker-Thread-980027)  
[ WicketURLEncoder.java:203:WARN ] No current Application found -  
defaulting encoding to UTF-8
2010-02-01 11:01:31,239 (default-invoker-Thread-980027)  
[ServiceEcaCondition.java:155:WARN ] From Field (communicationEventId)  
is not found in context for sendMail, defaulting to null.
2010-02-01 11:01:31,240 (default-invoker-Thread-980027)  
[ ServiceEcaRule.java:133:INFO ] For Service ECA [sendMail] on  
[commit] got false for condition: [partyId][equals][1][true][String]
2010-02-01 11:01:31,241 (default-invoker-Thread-980027)  
[ ServiceDispatcher.java:578:INFO ] Sync service [JobDispatcher/
sendMailFromScreen] finished in [57] milliseconds
2010-02-01 11:01:31,241 (default-invoker-Thread-980027)  
[ ServiceEcaRule.java:150:INFO ] Running Service ECA Service:  
createOrderNotificationLog, triggered by rule on Service:  
sendOrderConfirmation
2010-02-01 11:01:31,244 (default-invoker-Thread-980027)  
[ ServiceDispatcher.java:578:INFO ] Sync service [JobDispatcher/
sendOrderConfirmation] finished in [64] milliseconds

 From the thread list screen:

980536 default-invoker-Thread-980027
Running
1265050872766
sendOrderConfirmation
0
14145074
2046927

The time in MS keeps rising.

 From the job list screen for the same async service:

Job
ID
Pool
Run Time
Start Date/Time
Service
Status
End Date/Time
Use seperate logfile
Logfile

1265050872766
72203
pool
2010-02-01 11:01:12.000
2010-02-01 11:01:31.000
sendOrderConfirmation
SERVICE_RUNNING

N

I can't figure out why on the new machine, they are never marked as  
SERVICE_FINISHED. Makes no sense to me