This Bugzilla instance is a read-only archive of historic NetBeans bug reports. To report a bug in NetBeans please follow the project's instructions for reporting issues.

Bug 35336 - Hanging thread for 500ms-2000ms when writing to OutputWriter
Summary: Hanging thread for 500ms-2000ms when writing to OutputWriter
Status: RESOLVED INVALID
Alias: None
Product: platform
Classification: Unclassified
Component: Output Window (show other bugs)
Version: 3.x
Hardware: PC Windows ME/2000
: P3 blocker (vote)
Assignee: ivan
URL:
Keywords: PERFORMANCE
Depends on: 28297
Blocks: 35131
  Show dependency tree
 
Reported: 2003-08-08 02:51 UTC by Matthew Stevens
Modified: 2008-12-22 13:47 UTC (History)
3 users (show)

See Also:
Issue Type: DEFECT
Exception Reporter:


Attachments
example of an IDE hang while two thread write to System.out (12.02 KB, text/plain)
2003-08-16 03:59 UTC, Matthew Stevens
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Matthew Stevens 2003-08-08 02:51:14 UTC
While porting S1AF module to Studio 5 I experienced severe 
latency when our own debug messages were enabled.  For less 
than 300 lines of debug written to the our Debug tab in the 
Output Window...we saw almost a 2 minute hang.  Stack trace 
during hang shows the problem to be in OutputTabTerm.java

"JATO JSP Tasks" daemon prio=2 tid=0x2daa4f38 nid=0x77c in 
Object.wait() [2fc1f000..2fc1fd94]
       at java.lang.Object.wait(Native Method)
       at 
org.netbeans.core.output.OutputTabTerm$OutTermPane.invokeNow
(OutputTabTerm.java:2440)
       - locked  (a java.lang.Object)
       at 
org.netbeans.core.output.OutputTabTerm$OutTermPane.access$27
00(OutputTabTerm.java:751)
       at 
org.netbeans.core.output.OutputTabTerm$OutTermPane$TermOutpu
tWriter.println(OutputTabTerm
.java:1471)
       at java.io.PrintWriter.println(PrintWriter.java:516)
       - locked  (a java.io.OutputStreamWriter)
       at com.sun.jato.tools.sunone.Debug.debug
(Debug.java:407)
       at com.sun.jato.tools.sunone.Debug.verboseDebug
(Debug.java:400)


source code for OutputTabTerm:invokeNow(Runnable) reveals 
cases of waiting for 500ms.

Our workaround was to send our debug to System.out

Another behavioral problem with the 3.5 implementation was 
that OutputWriter.println calls were being displayed 
severely OUT OF ORDER.  There really is little value in 
having items printed out of order...it requires keeping a 
counting sequence on each print as well as a millesecond 
timestamp to make any use of the results.

Tests were performed on dual process Intel Xeon so it was a 
thorough test of the MT codepath.
Comment 1 mslama 2003-08-13 11:08:37 UTC
Assigning to terminal emulator (output window).
Comment 2 _ tboudreau 2003-08-13 14:35:45 UTC
OutputTabTerm is in pretty dire need of a 
rewrite/simplification.  Since the new window system spec
calls for changes in it, that work should be incorporated
into the other changes it needs - simplest my be to rewrite
it from the ground up.

In particular, the use of a timer for coalescing repaints
probably doesn't make a lot of sense - repaint (nnn ms) would
be much simpler;  new data should simply be timestamped and
queued, and the painting should be handled on the AWT thread
without rescheduling.
Comment 3 _ tboudreau 2003-08-15 13:03:25 UTC
FWIW, see patch attached to 28297 - it appears that all of the 
complex threading code in OutputTabTerm may be able to be safely
deleted, possibly using trivial synchronization to accomplish
what we need.
Comment 4 Matthew Stevens 2003-08-16 03:58:24 UTC
Tim, as I said we are logging to STDOUT or STDERR now and avoiding the
terminal.  However, I can test this patch you suggested if you need me
to.  I occasionally get a hang which will only go away AFTER I do a
control break to get the Full THread Dump.  I have gotten this about
3-4 times in the last couple of weeks.  It appears to happen when you
write to the System.out concurrently.  I am attaching a
FullThreadDump1.txt which shows one thread (Folder Recognizer) trying
to log during a DataObject creation while another thread (AWT) is
calling createSheet.

Please note that this is NOT in our critical path for we do not expect
to enable logging unless we are in development.  I figured this strack
trace would be interesting to you.  It is just FYI. -matt-
Comment 5 Matthew Stevens 2003-08-16 03:59:35 UTC
Created attachment 11338 [details]
example of an IDE hang while two thread write to System.out
Comment 6 _ tboudreau 2003-11-19 22:33:52 UTC
While in the long run, the problem is oversynchronization, looking at
your stack trace, I may be able to offer you a workaround:

org.openide.io.InputOutput allows you to specify that stderr and
stdout be routed to two separate windows in a splitpane inside the
output window.

Since it looks like the contention is for a single PrintStream, if,
when setting up your output you call InputOutput.setErrSeparated(true)
(on whatever implementation you get from, I guess, Lookup), that
should at least mean that stderr and stdout are not trying to write to
the same place - it might clear up your problem.  Let me know if it
works out for you.
Comment 7 Matthew Stevens 2003-11-20 14:05:12 UTC
I think there are more systemic problems with the InputOutput than
just the windows UI problems.  This summer, to work around the issues
of logging to the output windows we added options to simply have this
log stream passed to STDOUT or STDERR...either or.  What we found is
that we still would hang fairly often 50% of the even writing to the
cmd console which was STDOUT.  Only if we directed to STDERR which
reached the ide.log did we NOT have hangs.

Please refer to the posting of 2003-08-15 where I explained that we no
longer use the windows and its hangs when using STDOUT...see stack trace.
Comment 8 _ tboudreau 2003-11-20 22:18:32 UTC
Well, you'll hear no argument from me that there are systemic
problems.  What I'd like to do (at the moment output window stuff is
not at the top of the priority list, for better or worse), is to go
through it and remove all of the synchronization code throught the
codepaths all the way to term (basically just means writing some
unsynchronized stream classes).  Then see where the problems are and
create a single entry point for managing thread safety.

Right now there are way too many things grabbing assorted locks to do
simple operations.  The patch attached to 28297 demonstrates pretty
clearly that most of the threading problems can be cleared up this way
(it just relies on the synchronization in Document to do everything).
Comment 9 _ tboudreau 2004-04-19 14:06:34 UTC
Reassigning to Marek, new owner of output window and help system
Comment 10 Antonin Nebuzelsky 2004-05-03 13:46:29 UTC
Marku, can you evaluate this issue for promo-D? This seems to me a
higher priority than P4... Thanks.
Comment 11 Antonin Nebuzelsky 2004-06-11 17:42:57 UTC
Needs evaluation for promo-D.
Is terminal emulator interesting for promo-D after the new output
window was implemented?
Comment 12 Marian Mirilovic 2006-09-25 10:50:35 UTC
The core team has not been responsible for terminal emulator for long time, so
reassigne all opened issues to responsible person.
Comment 13 ivan 2007-10-11 19:25:28 UTC
Sigh,
The problmatic code with the sleeps in not in the terminalemulator, but
in the (old) output module.
Presumably output2 doesn't suffer from this, but that is up to
the maintainers of output2 to determine.


Comment 14 t_h 2008-06-22 22:52:58 UTC
It is not relevant to output2.