Bug 270070 - significant slowdown when debugging (was: editing certain files)
significant slowdown when debugging (was: editing certain files)
Status: RESOLVED FIXED
Product: cnd
Classification: Unclassified
Component: Debugger
Dev
PC Linux
: P1 (vote)
: Dev
Assigned To: Maria Tishkova
issues@cnd
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2017-03-14 16:10 UTC by tbrunhoff
Modified: 2017-08-12 02:06 UTC (History)
0 users

See Also:
Issue Type: DEFECT
:


Attachments
snapshot (22.91 KB, application/octet-stream)
2017-03-14 16:31 UTC, tbrunhoff
Details
snapshot (118.84 KB, application/octet-stream)
2017-03-14 16:40 UTC, tbrunhoff
Details
.npss file attached from NetBeans (104.10 KB, application/x-npss)
2017-03-15 16:31 UTC, tbrunhoff
Details
.npss file attached from NetBeans (74.61 KB, application/x-npss)
2017-03-31 16:34 UTC, tbrunhoff
Details
gdb log (36.70 KB, text/x-log)
2017-03-31 16:35 UTC, tbrunhoff
Details
gdb log (403.71 KB, text/x-log)
2017-05-02 14:55 UTC, tbrunhoff
Details
messages log (105.12 KB, text/x-log)
2017-05-02 14:55 UTC, tbrunhoff
Details
.npss file attached from NetBeans (133.47 KB, application/x-npss)
2017-05-02 14:56 UTC, tbrunhoff
Details

Note You need to log in before you can comment on or make changes to this bug.
Description tbrunhoff 2017-03-14 16:10:48 UTC
I don't know what it is about certain files (it does not appear to be the size), but when editing, the ide will freeze usually 3-4 seconds.  In rare occasions, I've seen it freeze up to 15 seconds. It always recovers.

The attached ide snapshot shows a profile captured over 11 seconds, where two newlines were added to a 452-line source code file. The UI was frozen for several seconds.

Product Version: NetBeans IDE Dev (Build 201701090001)
Updates: Updates available
Java: 1.8.0_45; Java HotSpot(TM) 64-Bit Server VM 25.45-b02
Runtime: Java(TM) SE Runtime Environment 1.8.0_45-b14
System: Linux version 4.1.13-100.fc21.x86_64 running on amd64; UTF-8; en_US (nb)
User directory: /home/toddb/.netbeans/dev
Cache directory: /home/toddb/.cache/netbeans/dev
Comment 1 tbrunhoff 2017-03-14 16:31:30 UTC
Created attachment 163833 [details]
snapshot

Note that the "attach ide snapshot to bug" in the ide did not allow me to log in (and then locked me out for 5 minutes).
Comment 2 tbrunhoff 2017-03-14 16:40:22 UTC
Created attachment 163834 [details]
snapshot

This shapshot was taken when adding a single line to the same file, and the ide was frozen for 10 seconds.
Comment 3 tbrunhoff 2017-03-14 16:49:42 UTC
Exiting the ide and doing...

rm -rf ~/.cache/netbeans/dev/cnd/model/

seems to remove the slowdowns for a while.
Comment 4 Alexander Simon 2017-03-15 10:34:20 UTC
It looks like debugger is listener of document changes and consume a lot of time to process events.
Comment 5 tbrunhoff 2017-03-15 14:27:18 UTC
Ok, I have not been paying attention to whether the debugger is running when I am editing. Frequently, I bounce back and forth between editing and debugging. That could explain a related problem where single-stepping in the debugger is very painful.
Comment 6 tbrunhoff 2017-03-15 16:31:04 UTC
Created attachment 163853 [details]
.npss file attached from NetBeans

.npss file
Comment 7 tbrunhoff 2017-03-15 16:36:08 UTC
This last attachment is from simply stepping through about 8 lines of code ("step over"). Each line took 3 to 8 seconds. I should note that it is slow whether I do the stepping in the UI or in the IDE's debugger console. However, running gdb separately, stepping is instantaneous.

Please tell me if this represents the same bug, or whether I should file a different one.
Comment 8 Maria Tishkova 2017-03-16 23:11:36 UTC
(In reply to tbrunhoff from comment #7)
> This last attachment is from simply stepping through about 8 lines of code
> ("step over"). Each line took 3 to 8 seconds. I should note that it is slow
> whether I do the stepping in the UI or in the IDE's debugger console.
> However, running gdb separately, stepping is instantaneous.
> 
> Please tell me if this represents the same bug, or whether I should file a
> different one.

The problem with slow stepping was solved in trunk (see https://netbeans.org/bugzilla/show_bug.cgi?id=269898).
Please try latest version and let me know if you still have significant slow down.
Also opened Debugging View can slow down stepping (information about all stack frames for all threads is requested) and if you have Debugging View+Locals windows opened it will lead to sooo slow step..

Will take a look at editing issue tomorrow
Comment 9 Vladimir Voskresensky 2017-03-18 11:11:31 UTC
Hi Todd, 

I faced similar problem and my trick to have fast single-stepping (as fast as in native gdb in CL) after recent Maria's fixes:
in Tools->Options->C++ turn off "Show arguments values in CallStack..."
and turn off "Balloon Expr Evaluation".
In fact balloon evaluation is very helpful, so turning off this checkbox disables only automatic balloon evaluation when you hover mouse over any identifier in editor.
But even when it is OFF you still can select non-empty expression in code and when you hover the mouse above selection => you will see the value in balloon

Hope it helps,
Vladimir.
Btw, in this particular case it would be helpful to get your debugger log additional to npss snapshot to check what's going on in debugger
Comment 10 Maria Tishkova 2017-03-22 16:55:59 UTC
Comment from tbrunhoff:

Thanks to both of you for the suggestions, all of which appear to help. It looks like this also addresses the editing issue too. The ide has been up for at least 18 hours and I checked several files (adding one line) and there were no delays. Nice work. Lets call this fixed, for now.

It would be nice if Debugging View+Locals window did not slow down stepping, but I'll wait to complain about that if it turns out to be an issue for me.


-------


Will mark it as fixed
Comment 11 tbrunhoff 2017-03-31 16:33:50 UTC
This is about slow stepping, not slow editing (which appears to be fine). However...

Based on suggestions above I have:
- turned off "Show arguments values in CallStack..."
- turned off "Balloon Expr Evaluation".
- updated to the version below, which post-dates the comments about Maria's fixes.

For a while the stepping seemed to be good. But recently, it has gotten very slow again.  I've attached a profile and the gdb logs.

Product Version: NetBeans IDE Dev (Build 201703190002)
Updates: Updates available
Java: 1.8.0_45; Java HotSpot(TM) 64-Bit Server VM 25.45-b02
Runtime: Java(TM) SE Runtime Environment 1.8.0_45-b14
System: Linux version 4.1.13-100.fc21.x86_64 running on amd64; UTF-8; en_US (nb)
User directory: /home/toddb/.netbeans/dev
Cache directory: /home/toddb/.cache/netbeans/dev
Comment 12 tbrunhoff 2017-03-31 16:34:45 UTC
Created attachment 163989 [details]
.npss file attached from NetBeans

.npss file
Comment 13 tbrunhoff 2017-03-31 16:35:47 UTC
Created attachment 163990 [details]
gdb log
Comment 14 Maria Tishkova 2017-04-03 09:19:23 UTC
(In reply to tbrunhoff from comment #11)
> This is about slow stepping, not slow editing (which appears to be fine).
> However...
> 
> Based on suggestions above I have:
> - turned off "Show arguments values in CallStack..."
> - turned off "Balloon Expr Evaluation".
> - updated to the version below, which post-dates the comments about Maria's
> fixes.
> 
> For a while the stepping seemed to be good. But recently, it has gotten very
> slow again.  I've attached a profile and the gdb logs.
> 
> Product Version: NetBeans IDE Dev (Build 201703190002)
> Updates: Updates available
> Java: 1.8.0_45; Java HotSpot(TM) 64-Bit Server VM 25.45-b02
> Runtime: Java(TM) SE Runtime Environment 1.8.0_45-b14
> System: Linux version 4.1.13-100.fc21.x86_64 running on amd64; UTF-8; en_US
> (nb)
> User directory: /home/toddb/.netbeans/dev
> Cache directory: /home/toddb/.cache/netbeans/dev


I looked at GDB log  you attached and I do not see stepping at all. Please attach GDB log which can provide more information. When you say "recently it became slow" does it mean you didn't restart IDE for a while or what?
Comment 15 Maria Tishkova 2017-04-05 09:01:05 UTC
(In reply to tbrunhoff from comment #13)
> Created attachment 163990 [details]
> gdb log

Please provide GDb logs which demonstrate the problem with stepping. The GDB log you have attached doesn't contain any steps
Comment 16 tbrunhoff 2017-04-05 14:33:59 UTC
I apologize for taking so long.  I hope to get back to debugging today.
Comment 17 Maria Tishkova 2017-04-10 11:10:15 UTC
Do not have information enough to fix this problem. Please provide GDB logs and re-open it
Comment 18 tbrunhoff 2017-05-02 14:54:35 UTC
The debugging slowdown showed up again this week, first with netbeans-dev-201704160002 and then with the newer build shown below. Stepping through code took 5-20 seconds for each step.

Balloon expression evaluation is turned off
Show Argument values in call stack and debugging view windows is turned off.

I noticed there was a new button next to the "profile ide" button about monitoring io events. I could not find any info about it.

I'll attach profile, gdb log and messages log.


Product Version: NetBeans IDE Dev (Build 201705010001)
Updates: Updates available
Java: 1.8.0_45; Java HotSpot(TM) 64-Bit Server VM 25.45-b02
Runtime: Java(TM) SE Runtime Environment 1.8.0_45-b14
System: Linux version 4.1.13-100.fc21.x86_64 running on amd64; UTF-8; en_US (nb)
User directory: /home/toddb/.netbeans/dev
Cache directory: /home/toddb/.cache/netbeans/dev
Comment 19 tbrunhoff 2017-05-02 14:55:14 UTC
Created attachment 164224 [details]
gdb log
Comment 20 tbrunhoff 2017-05-02 14:55:59 UTC
Created attachment 164225 [details]
messages log
Comment 21 tbrunhoff 2017-05-02 14:56:35 UTC
Created attachment 164226 [details]
.npss file attached from NetBeans

.npss file
Comment 22 tbrunhoff 2017-05-02 15:11:08 UTC
From the gdb log, even though "Show Argument values in call stack and debugging view windows" is turned off, argument values are still captured by gdb.  The only thing that setting seems to do is suppress the values in the call stack window.

Load average on the machine is running at about 0.5.  This is a skylake i7-6700K @ 4.00GHz with 64GB of memory. Config is set as follows:

netbeans_default_options="-J-client -J-XX:+UseConcMarkSweepGC -J-XX:+CMSClassUnloadingEnabled -J-XX:+CMSPermGenSweepingEnabled -J-XX:CompileThreshold=100 -J-Xms256m -J-Xmx6000m -J-Xss2m -J-XX:PermSize=32m -J-XX:MaxPermSize=384m -J-Dnetbeans.logger.console=true -J-ea -J-Dapple.laf.useScreenMenuBar=true -J-Dapple.awt.graphics.UseQuartz=true -J-Dsun.java2d.noddraw=true -J-Dcnd.project.name.hidden.paths=\"/home/toddb/src\" -J-Dorg.netbeans.modules.keyring.level=0 -J-Djava.library.path=/opt/CollabNet_Subversion/lib"
Comment 23 Maria Tishkova 2017-05-03 09:04:39 UTC
Please clarify

(In reply to tbrunhoff from comment #22)
> From the gdb log, even though "Show Argument values in call stack and
> debugging view windows" is turned off, argument values are still captured by
> gdb.  The only thing that setting seems to do is suppress the values in the
> call stack window.

How did you understand that? From what I see in GDB log 
-stack-list-arguments command always invoked with "0" which means (see GDB MuI docs for more details) : 

If print-values is 0 or --no-values, print only the names of the variables; if it is 1 or --all-values, print also their values; 


Do you have slow stepping when do it for Assembler? 


Also I am just wondering if you will close Variables/Watches will it speed up the step? And use balloon evaluation instead.


And one more.. You wrote the stepping was good but later you have faced slow down again.. Was the usage scenario changed? Have you started to use Disasm window?

> 
> Load average on the machine is running at about 0.5.  This is a skylake
> i7-6700K @ 4.00GHz with 64GB of memory. Config is set as follows:
> 
> netbeans_default_options="-J-client -J-XX:+UseConcMarkSweepGC
> -J-XX:+CMSClassUnloadingEnabled -J-XX:+CMSPermGenSweepingEnabled
> -J-XX:CompileThreshold=100 -J-Xms256m -J-Xmx6000m -J-Xss2m
> -J-XX:PermSize=32m -J-XX:MaxPermSize=384m -J-Dnetbeans.logger.console=true
> -J-ea -J-Dapple.laf.useScreenMenuBar=true
> -J-Dapple.awt.graphics.UseQuartz=true -J-Dsun.java2d.noddraw=true
> -J-Dcnd.project.name.hidden.paths=\"/home/toddb/src\"
> -J-Dorg.netbeans.modules.keyring.level=0
> -J-Djava.library.path=/opt/CollabNet_Subversion/lib"
Comment 24 tbrunhoff 2017-05-03 14:53:09 UTC
> How did you understand that?

Ok.  That was a guess on my part. Ignore that comment.

> Do you have slow stepping when do it for Assembler?


> Also I am just wondering if you will close Variables/Watches will it speed up the step? And use balloon evaluation > instead.

Yes, with variables and watches closed it goes back to normal stepping speed. So it is something in the variable evaluation that is slow. Surely you can't be serious that I should always keep the variables/watches windows closed and use bubble eval. That's a workaround, not a fix.

> And one more.. You wrote the stepping was good but later you have faced slow
> down again.. Was the usage scenario changed? Have you started to use Disasm 
> window?

Interesting question. And yes, single stepping in disasm window is very slow (with variables view open).  Here's a short chunk of code and all but two lines took 3-4 seconds for each step. 

!        case generatedGrid:
!            {
!                const int size = 100;
GenericCodec::Generator::transform(AutoRefPtr<GenericCodec::BasebandFrame>)()
GenericCodec::Generator::transform(AutoRefPtr<GenericCodec::BasebandFrame>)+509: movl   $0x64,-0x14(%rbp)
!                if (nPlanarBytesFor(mFrame->getDesc().getDepth()) == 2) {
GenericCodec::Generator::transform(AutoRefPtr<GenericCodec::BasebandFrame>)+516: mov    -0x160(%rbp),%rax
GenericCodec::Generator::transform(AutoRefPtr<GenericCodec::BasebandFrame>)+523: add    $0x198,%rax
GenericCodec::Generator::transform(AutoRefPtr<GenericCodec::BasebandFrame>)+529: mov    %rax,%rdi
GenericCodec::Generator::transform(AutoRefPtr<GenericCodec::BasebandFrame>)+532: callq  0x45c956 <AutoRefPtr<GenericCodec::BasebandFrame>::operator->() const>
GenericCodec::Generator::transform(AutoRefPtr<GenericCodec::BasebandFrame>)+537: mov    %rax,%rdi
GenericCodec::Generator::transform(AutoRefPtr<GenericCodec::BasebandFrame>)+540: callq  0x49194a <GenericCodec::BasebandFrame::getDesc()>
GenericCodec::Generator::transform(AutoRefPtr<GenericCodec::BasebandFrame>)+545: mov    %rax,%rdi
GenericCodec::Generator::transform(AutoRefPtr<GenericCodec::BasebandFrame>)+548: callq  0x49150e <GenericCodec::FrameDesc::getDepth() const>
GenericCodec::Generator::transform(AutoRefPtr<GenericCodec::BasebandFrame>)+553: mov    %eax,%edi
GenericCodec::Generator::transform(AutoRefPtr<GenericCodec::BasebandFrame>)+555: callq  0x45bd56 <GenericCodec::nPlanarBytesFor(GenericCodec::ComponentDepth)>
GenericCodec::Generator::transform(AutoRefPtr<GenericCodec::BasebandFrame>)+560: cmp    $0x2,%eax
GenericCodec::Generator::transform(AutoRefPtr<GenericCodec::BasebandFrame>)+563: sete   %al
GenericCodec::Generator::transform(AutoRefPtr<GenericCodec::BasebandFrame>)+566: test   %al,%al
GenericCodec::Generator::transform(AutoRefPtr<GenericCodec::BasebandFrame>)+568: je     0x48e9d5 <GenericCodec::Generator::transform(AutoRefPtr<GenericCodec::BasebandFrame>)+677>
Comment 25 tbrunhoff 2017-05-03 15:02:23 UTC
In the context of the assembly code above there are only two local variables: size and this. Using the gdb console these evaluate as follows. Why would this cause a 3-4 second delay in stepping?  It must be that there is more evaluation being performed. Probably more than is necessary.
-------------------------------------------------------------------
p *this
(gdb) 
$4 = {<GenericCodec::Transform> = {<GenericCodec::MediaOp> = {<GenericCodec::Allocator> = {<Owner> = {_vptr.Owner = 0x1543250 <vtable for GenericCodec::Generator+16>, mInstance = 6, mBaseName = 0x184e5a0 \"generator2\", mName = {m_bufsize = 128, m_buf = 0x1850660 \"generator2#6\", m_ptr = 0x1850660 \"generator2#6\"}, static sInstance = {m_count = 7}}, mMutex = {mutex_ = {__data = {__lock = 0, __count = 1, __owner = 0, __nusers = 0, __kind = 32, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, __size = \"\\000\\000\\000\\000\\001\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000 \\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\", __align = 4294967296}, locker_ = 0, lockerp_ = -1, dstate_ = 2}, mRecycle = GenericCodec::Allocator::deleteOnZero, mAlloc = {_M_t = {_M_impl = {<std::allocator<std::_Rb_tree_node<std::pair<GenericCodec::RefAlloc* const, GenericCodec::RefAlloc*> > >> = {<__gnu_cxx::new_allocator<std::_Rb_tree_node<std::pair<GenericCodec::RefAlloc* const, GenericCodec::RefAlloc*> > >> = {<No data fields>}, <No data fields>}, _M_key_compare = {<std::binary_function<GenericCodec::RefAlloc*, GenericCodec::RefAlloc*, bool>> = {<No data fields>}, <No data fields>}, _M_header = {_M_color = std::_S_red, _M_parent = 0x1850c60, _M_left = 0x1850c60, _M_right = 0x1850c60}, _M_node_count = 1}}}, mFree = {<std::_List_base<GenericCodec::RefAlloc*, std::allocator<GenericCodec::RefAlloc*> >> = {_M_impl = {<std::allocator<std::_List_node<GenericCodec::RefAlloc*> >> = {<__gnu_cxx::new_allocator<std::_List_node<GenericCodec::RefAlloc*> >> = {<No data fields>}, <No data fields>}, _M_node = {_M_next = 0x1850550, _M_prev = 0x1850550}}}, <No data fields>}, mHiWat = 1, mMemPool = {m_ptr = 0x164c0c0 <SingletonHelper<MediaGraph::LocalMemoryPool<1u> >::staticSingleton(MediaGraph::LocalMemoryPool<1u>*&)::s_singleton>}, mSem = {m_ptr = 0x0}, mTraceAlloc = false}, mOpId = {instance = 6, nCpu = 1, opType = GenericCodec::generateType, codecType = GenericCodec::transformType}, mPerf = {m_ptr = 0x0}, mNumIn = 0, mNumOut = 0, mHiwatActive = 1, mNewHiwat = false, mThreadGroups = @0x184dd78}, mOutDesc = {imageStruct = {depth = GenericCodec::depth10Bit, sampling = GenericCodec::cs422, nPlanes = 3, nChannels = 3, chanPerPixel = 1, lumaStride = 8192, chromaStride = 4094}, fourCc = {u = {cc = \"W210\", code = 808530519}}, tag = {s = {startTime = 0, endTime = 0, isSet = false, tag = 0, generation = 0}}, isLate = false, displayTime = 0, rate = {numerator = 25, denominator = 1, scanType = mediaVideoScanInterlaced}, dim = {w = 3840, h = 2160}, tRef = 0, sInfo = {encoding = 1 '\\001', refType = 14 '\\016', displayOffset = -128 '\\200', temporalOffset = -128 '\\200', size = 0, static invalidFrame = 9223372036854775807}, checksum = 0}, mCallback = 0x184ea88, mNoopWarning = false}, mType = GenericCodec::generatedGrid, mCount = 0, mFrame = {m_ptr = 0x1850ad0}}
(gdb)
p size
(gdb) 
$5 = 0
Comment 26 Maria Tishkova 2017-08-11 09:43:09 UTC
changeset:   304439:65beb5b68407
tag:         tip
user:        Maria Dalmatova <mromashova@netbeans.org>
date:        Fri Aug 11 12:29:08 2017 +0300
summary:    fix for bz#270963 - gdb continues automatically and bz#270070 - significant slowdown when debugging (was: editing certain files)
1) fixed problem with jumping when breakpoint hitted
2) minimized enabling/disabling breakpoints for data expression evaluation that speed up stepping
3) show tooltip with OUT_OF_SCOPT value if selected expression is incorrect



I will mark it as resolved, please test the fix and re-open if still re-producible
Comment 27 Quality Engineering 2017-08-12 02:06:42 UTC
Integrated into 'main-silver', will be available in build *201708120001* on http://bits.netbeans.org/dev/nightly/ (upload may still be in progress)

Changeset: http://hg.netbeans.org/main-silver/rev/65beb5b68407
User: Maria Dalmatova <mromashova@netbeans.org>
Log: fix for bz#270963 - gdb continues automatically and bz#270070 - significant slowdown when debugging (was: editing certain files)
1) fixed problem with jumping  when breakpoint hitted
2) minimized enabling/disabling breakpoints for data expression evaluation that speed up stepping
3) show tooltip with OUT_OF_SCOPT value if selected expression is incorrect


By use of this website, you agree to the NetBeans Policies and Terms of Use. © 2014, Oracle Corporation and/or its affiliates. Sponsored by Oracle logo