Skip to main content

Infinite wait in SIRequestorImpl.waitForCompletion() causes RI to freeze

Please note these java.net forums are being decommissioned and use the new and improved forums at https://community.oracle.com/community/java.
2 replies [Last post]
BigiCP
Offline
Joined: 2011-03-28

The entity which needs some si data will request to SICache and will wait in SIRequestorImpl.waitForCompletion(). This method uses an infinite wait (). It will come out of wait, if it is getting notifyFailure()/notifySuccess().

All the asynchronous requests to SI cache will be added to corresponding queue and will try to get the data. If the requested item is available the data will be returned using SIRequestor.notifySuccess(). If it is getting SINotAvailableYetException it simply returns and whenever the data is available the thread will be notified. If the data is not available within a predefined period (15sec) the thread will be notified as notifyFailure() by the TVTimerSpec scheduled at the initialization of SIcacheImpl. This spec times out periodically and removes old requests from the queue.

All the timer tasks are scheduled on the same timer and timer uses a single thread to execute all the tasks sequentially. Consider a scenario: During the execution of one timer task, it wants some SI data and posts request to the SICache and waits on SIRequestorImpl.waitForCompletion(). For the thread to come out of waitForCompletion() somehow it should be notified. SICache is getting SINotAvailableYetException and hence it will not be giving notifySuccess(). The timer thread is blocked and hence the asynchrounous timer tasks will not be expired and it will not be getting notifyFailure().

I will explain a scenario in which RI is running in debug mode:
Connection to VCL via telnet is failed.
Calls the method SICacheImpl.retrieveTsId() and it gets SINotAvailableYetException. So the thead waits to get notified.
This is the stack trace to show how it reached this method.
at org.cablelabs.impl.manager.service.SICacheImpl.retrieveTsID(SICacheImpl.java:1853)
20110519 13:58:02.516 INFO RI.Stack.StdOut- at org.cablelabs.impl.service.javatv.transport.TransportStreamImpl.retrieveTsID(TransportStreamImpl.java:252)
20110519 13:58:02.516 INFO RI.Stack.StdOut- at org.cablelabs.impl.service.TransportStreamExt.getTransportStreamID(TransportStreamExt.java:151)
20110519 13:58:02.516 INFO RI.Stack.StdOut- at org.cablelabs.impl.service.TransportStreamExt$DavicTransportStream.toString(TransportStreamExt.java:341)
20110519 13:58:02.516 INFO RI.Stack.StdOut- at java.lang.String.valueOf(String.java:2310)
20110519 13:58:02.516 INFO RI.Stack.StdOut- at java.lang.StringBuffer.append(StringBuffer.java:454)
20110519 13:58:02.516 INFO RI.Stack.StdOut- at org.cablelabs.impl.davic.net.tuning.NetworkInterfaceImpl$TransportStreamAdapter.toString(NetworkInterfaceImpl.java:1990)
20110519 13:58:02.516 INFO RI.Stack.StdOut- at java.lang.String.valueOf(String.java:2310)
20110519 13:58:02.516 INFO RI.Stack.StdOut- at java.lang.StringBuffer.append(StringBuffer.java:454)
20110519 13:58:02.516 INFO RI.Stack.StdOut- at org.cablelabs.impl.davic.net.tuning.NetworkInterfaceImpl$NIStateMachine.updateTSA(NetworkInterfaceImpl.java:1491)
20110519 13:58:02.516 INFO RI.Stack.StdOut- at org.cablelabs.impl.davic.net.tuning.NetworkInterfaceImpl$NIStateMachine.handleTuneUnsync(NetworkInterfaceImpl.java:1299)
20110519 13:58:02.516 INFO RI.Stack.StdOut- at org.cablelabs.impl.davic.net.tuning.NetworkInterfaceImpl$TuneRequest$1.run(NetworkInterfaceImpl.java:1785)
20110519 13:58:02.516 INFO RI.Stack.StdOut- at org.cablelabs.impl.manager.application.WorkerTask.run(WorkerTask.java:128)
20110519 13:58:02.532 INFO RI.Stack.StdOut- at org.cablelabs.impl.manager.application.AppExecQueue$1.run(AppExecQueue.java:120)
20110519 13:58:02.532 INFO RI.Stack.StdOut- at java.lang.Thread.run(Thread.java:715)
20110519 13:58:02.532 INFO RI.Stack.StdOut- at java.lang.Thread.startup(Thread.java:785)

Meanwhile, tune timeout is happening and fires the task. In this case also, it calls SICacheImpl.retrieveTsId() and gets SINotAvailableYetException.
Stack trace to show how it reached this method:
20110519 13:58:11.610 INFO RI.Stack.StdOut- at java.lang.Thread.dumpStack(Thread.java:1339)
20110519 13:58:11.626 INFO RI.Stack.StdOut- at org.cablelabs.impl.manager.service.SICacheImpl.retrieveTsID(SICacheImpl.java:1853)
20110519 13:58:11.626 INFO RI.Stack.StdOut- at org.cablelabs.impl.service.javatv.transport.TransportStreamImpl.retrieveTsID(TransportStreamImpl.java:252)
20110519 13:58:11.626 INFO RI.Stack.StdOut- at org.cablelabs.impl.service.TransportStreamExt.getTransportStreamID(TransportStreamExt.java:151)
20110519 13:58:11.626 INFO RI.Stack.StdOut- at org.cablelabs.impl.service.TransportStreamExt$DavicTransportStream.toString(TransportStreamExt.java:341)
20110519 13:58:11.626 INFO RI.Stack.StdOut- at java.lang.String.valueOf(String.java:2310)
20110519 13:58:11.626 INFO RI.Stack.StdOut- at java.lang.StringBuffer.append(StringBuffer.java:454)
20110519 13:58:11.626 INFO RI.Stack.StdOut- at org.cablelabs.impl.davic.net.tuning.NetworkInterfaceImpl$TransportStreamAdapter.toString(NetworkInterfaceImpl.java:1990)
20110519 13:58:11.626 INFO RI.Stack.StdOut- at java.lang.String.valueOf(String.java:2310)
20110519 13:58:11.641 INFO RI.Stack.StdOut- at java.lang.StringBuffer.append(StringBuffer.java:454)
20110519 13:58:11.641 INFO RI.Stack.StdOut- at org.cablelabs.impl.davic.net.tuning.NetworkInterfaceImpl$TuneRequest.toString(NetworkInterfaceImpl.java:1693)
20110519 13:58:11.641 INFO RI.Stack.StdOut- at java.lang.String.valueOf(String.java:2310)
20110519 13:58:11.641 INFO RI.Stack.StdOut- at java.lang.StringBuffer.append(StringBuffer.java:454)
20110519 13:58:11.641 INFO RI.Stack.StdOut- at org.cablelabs.impl.davic.net.tuning.NetworkInterfaceImpl$TuneRequest.timerWentOff(NetworkInterfaceImpl.java:1815)
20110519 13:58:11.641 INFO RI.Stack.StdOut- at javax.tv.util.TVTimerSpec.notifyListeners(TVTimerSpec.java:304)
20110519 13:58:11.641 INFO RI.Stack.StdOut- at org.cablelabs.impl.manager.timer.TimerMgrJava2$TVTimerImpl$1.run(TimerMgrJava2.java:435)
20110519 13:58:11.641 INFO RI.Stack.StdOut- at java.util.TimerThread.mainLoop(Timer.java:498)
20110519 13:58:11.641 INFO RI.Stack.StdOut- at java.util.TimerThread.run(Timer.java:428)
13:58:11.641 INFO RI.Stack.StdOut- at java.lang.Thread.startup(Thread.java:785)

Here for the timer thread to continue its investigation it wants to come out of SI retrieval operation. For that to happen another timer task is to be expired which will not happen since the thread is blocked. So finally RI comes to a freezed state.
I have observed this timer thread blocking issue in multiple scenarios and explained one example. But in all the observed scenarios tuning was failure.
What action do we have to take on this issue. Some suggestions :
1) When a timer task is expired move the task to a different thread(which is done in TaskTimerSpec) so that timer thread will not be blocked.
2) Remove the infinite wait() from the SIRequestorImpl.

Reply viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.
pmodem
Offline
Joined: 2008-12-17

Looks like in this particular scenario the getTransportStreamId() is being called from DavicTransportStream.toString() method. Transport stream Id retrieval implementation was recently updated to be a blocking call (via retrieveTsID()) and should not be called from toString(). Similar behavior was discovered in our testing and we updated the toString() method.
However, the issue you identified with respect to timer tasks still exists. We are discussing internally to come up with a solution. Thanks.

BigiCP
Offline
Joined: 2011-03-28

Any update on the issue related to timer task?

Thanks.