Any advice for debugging REALLY long OSGI integration test launches?

[Gerald Runion]

When I launch any one of our integration tests in my workspace it takes on the order of 5 mins for said integration test to launch. This happens even in the circumstances when all projects in the workspace are up to date. The progress dialog says "build before launch" and hangs 36% for what seems like forever. However, any output from the ErrorLog console has long since stopped.

Is there any other logging I can turn on to get some insight into what is happening between the time the BndTools builder finishes and the integration test launches?

Bndtools 3.2.0.REL-20160517-162512-g3a83c33 bndtools.main.feature.feature.group Bndtools

[Peter Kriens]

It is probably still building something but 5 mins sounds horrendous; that sounds like some timeout for file check/download.

You could turn on Build logging in the Preferences. This is logged in the error view.

Kind regards,

Peter Kriens

--
You received this message because you are subscribed to the Google Groups "bndtools-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to bndtools-user...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Gerald Runion]

I have the BndTools build log turned on and set to full. There is about a 3 min time between when the last item is added in the error log and the launch actually occurs.

[Gerald Runion]

So the crux of the matter is trying to figure out what is happening in the 3 mins that doesn't generate any output.

[Peter Kriens]

Could you run Wireshark to see if any network traffic is generated? And is the 3 min constant? Exactly 3 mins? My suspicion is a hanging connection.

Kind regards,

Peter Kriens

[Gerald Runion]

Just getting back to the office from some time away. I will see what I can do to check network traffic and to check the consistency of the delay.

[Gerald Runion]

Ran 4 tests....

network unplugged

7m5s

6m59s

network connected

7m4s

network connected all unnecessary projects closed and everything built

7m10s

So today it looks like a near constant 7 mins.

I have wireshark open and running. Any suggestions on what to filter on to look at traffic generated by eclipse?

[Peter Kriens]

In general any http traffic is interesting.

Kind regards,

Peter Kriens

[Gerald Runion]

Using filter "http && tcp" I see little traffic and nothing that correlates to launching the integration test. Based on that it doesn't appear to be network related.

[Gerald Runion]

I found how to run eclipse in debug mode and turn on extra logging.

...

...

...

Mon Jun 13 14:13:16 EDT 2016 - [Worker-9] org.eclipse.core.internal.events.AutoBuildJob(Building workspace): Auto-Build requested, needsBuild: false state: 4 delay: 100

Saved 217,252 bytes in variablesAndContainers.dat in 43ms

Mon Jun 13 14:18:16 EDT 2016 - [Worker-15] org.eclipse.core.internal.resources.DelayedSnapshotJob(Periodic workspace save.): Auto-Build requested, needsBuild: false state: 0 delay: 100

Mon Jun 13 14:18:16 EDT 2016 - [Worker-15] org.eclipse.core.internal.events.AutoBuildJob(Building workspace): Auto-Build requested, needsBuild: false state: 4 delay: 100

[Peter Kriens]

Could you put the Build logging on? This is Preferences/Bndtools/Build

Kind regards,

Peter Kriens

[Gerald Runion]

Attached.

[Peter Kriens]

Looking at the log there seems to be happening something before ‘org.syntech.entity’. Virtually all entries are less than a second except these

       !ENTRY bndtools.builder 1 0 2016-06-13 14:11:55.914 !MESSAGE ClasspathEntries org.syntech.unit.mainboard.ini

66 sec !ENTRY bndtools.builder 1 0 2016-06-13 14:13:01.241 !MESSAGE BUILD org.syntech.entity no build

       !ENTRY bndtools.builder 1 0 2016-06-13 14:47:40.942 !MESSAGE BUILD org.syntech.config.test no build

12 sec !ENTRY bndtools.builder 1 0 2016-06-13 14:47:52.815 !MESSAGE BUILD org.syntech.entity no build

       !ENTRY bndtools.builder 1 0 2016-06-13 14:47:04.318 !MESSAGE ClasspathEntries org.syntech.unit.mainboard.ini

35 sec !ENTRY bndtools.builder 1 0 2016-06-13 14:47:39.654 !MESSAGE BUILD org.syntech.entity no build

       !ENTRY bndtools.builder 1 0 2016-06-13 14:47:40.942 !MESSAGE BUILD org.syntech.config.test no build

12 sec !ENTRY bndtools.builder 1 0 2016-06-13 14:47:52.815 !MESSAGE BUILD org.syntech.entity no build

Something is working between the  … (Though I do not see the 7 mins in this log as you indicated?)

So a few more questions:

* Are you using code generation for org.syntech.entity? 

* What other builders then bndtools have you got defined in your projects? 

* Can you run the gradle build with  —info and send the log?

Kind regards,

Peter Kriens

<.log.txt>

[Gerald Runion]

Something is working between the  … (Though I do not see the 7 mins in this log as you indicated?)

Yeah, the time it takes to launch is largely after the last entry in the log for a given launch. So that log doesn't really do much to debug the problem. The long-ish build time of the entity project isn't really the issue here. The slow launch happens regardless of entity building or not.

So a few more questions:

* Are you using code generation for org.syntech.entity? That is our JPA project so there could very well be some background stuff going on there.

* What other builders then bndtools have you got defined in your projects? I don't believe so. 

* Can you run the gradle build with  —info and send the log? Sure, but I am not sure that will be helpful.

Also I will record a video of build/launch sequence with the error log and progress view visible so you can get a better feel for what is happening.

[Peter Kriens]

On 14 jun. 2016, at 14:31, Gerald Runion <gsru...@gmail.com> wrote:

Something is working between the  … (Though I do not see the 7 mins in this log as you indicated?)

Yeah, the time it takes to launch is largely after the last entry in the log for a given launch. So that log doesn't really do much to debug the problem. The long-ish build time of the entity project isn't really the issue here. The slow launch happens regardless of entity building or not.

The entity project is actually not build, that is why it is so odd it takes 12-66 secs.

So a few more questions:

* Are you using code generation for org.syntech.entity? That is our JPA project so there could very well be some background stuff going on there.

My suspicion is currently here. Could you send the .project files of all projects?

* What other builders then bndtools have you got defined in your projects? I don't believe so. 

* Can you run the gradle build with  —info and send the log? Sure, but I am not sure that will be helpful.

With the ——info I can see output from bnd …

Also I will record a video of build/launch sequence with the error log and progress view visible so you can get a better feel for what is happening.

Ok, but the gradle + .project files is also helpful.

Kind regards,

Peter kriens

[Gerald Runion]

I am gathering the info you requested.

In the meantime there has been another observation. If Eclipse is run with -clean or all the *.log files are deleted from workspace/.metadata, the integration test does not hang the first time it is ran but still hangs any subsequent launches.

[Gerald Runion]

Attached a zip containing a 

1) .project file, which I confirmed is identical (with the exception of project name) for every project in our workspace, 

2) The gradle output for running a particular integration test on org.syntech.eventprocessing

3) A video, showing an initial run of that integration test (with eclipse run with -clean) launching quickly and a subsequent launch of the test taking ~7 mins to launch.

[Peter Kriens]

Phew. Could you disable ‘build for launch’ in the Bndtools Preferences?

Kind regards,

Peter Kriens

<source_cpy.zip>

[Gerald Runion]

I have tried toggling that setting. The effect is that instead of the build hanging @ the 36% mark it hangs at the 6% mark.

[Gerald Runion]

Actually the behavior is a little different. Recording another video.

[Gerald Runion]

I hangs at the 6% mark till about the 6:30 mark. After which it invokes the BndTools builder and refreshing what appears to be all the open projects despite having the Window->Preferences->Bndtools->Launching->Build before launching option unchecked. Total time to launch has increased from around 7mins to >8mins.

[Peter Kriens]

I think we need to run a debug session :-(

Would you be willing to:

1) download the https://github.com/bndtools/bndtools repo

2) Find your eclipse.exe

3) start it from the commandline like on your workspace

c:> eclipse -vmargs -agentlib:jdwp=transport=dt_socket,address=127.0.0.1:8888,server=y,suspend=n

4) Open another eclipse instance on the bndtools workspace

5) Start a remote debugger to port 8888 from this instance

6) contact me on Skype? (pkriens)

Kind regards,

Peter Kriens

<capture.zip>

[Bryan Hunt]

Might it be easier to use VisualVM to profile the execution?

[Peter Kriens]

Never used Visual vm … might also be ok.

With the debugger in Bndtools I am quite comfortable :-)

Kind regards,

Peter Kriens

[Gerald Runion]

This has been debugged and an issue created....https://github.com/bndtools/bnd/issues/1501

[Jörg Wille]

I know that this is an old thread, but we are having the exact same problem with our software.
We are experiencing 3-10min delay before we can run or debug our software.
"The progress dialog says "build before launch" and hangs at 36%" always on all our machines (windows, mac, eclipse neon 2 or 3).

This behaviour happens on our (larger) framework as well as on a simple example program,
which I uploaded to https://github.com/joerg-wille/osgi-bnd-maven-example
Since we just recently switched from pde to bnd we have no comparisson.

We are using a maven standalone approach without workspace and since we want to benefit from the support of ranges for maven (btw. thank you Peter and BJ) we are using 3.4.0 development builds for bnd and bndtools.

Is this extremly slow running and debugging behaviour normal for standalone projects or for 3.4 dev-branch?
Or are we doing something real wrong?

(This is the only issue left before we can get our dev-team to switch, so it is really important for us.)

Thanks!

[Peter Kriens]

I just tried your workspace but it seems to work fine for me. I get both resolve and run in sub-second times on the launch run.bndrun file.

Also, in this case bnd does not run the build.

In the thread there are a number of tips to diagnose the problem. -runtrace=true, disable build before launch, enable logging of the builder, etc. You might want to try them out and send the files to me to take a look if you do not see the problem yourself.

Kind regards,

Peter Kriens

[Timothy Ward]

One question - is it possibly network related? What happens if you disable your networking first? I’ve seen issues where a corporate proxy/firewall causes a number of requests to time out as part of a build, slowing everything down a lot. Also, maven builds in Eclipse sometimes take a long time if the build dependency chain is very deep. Do you have your API built/packaged in the same projects as implementations?

Regards,

Tim

[Jörg Wille]

Thanks for your feedback.
Indeed, the project itself is not the problem!
I thought it would be a good idea to attach a small demo-project, which shows the problem, and loose any dependencies into our big framework sources.
The truth is, that this small demo-project (and in fact all other projects) which I add to my workspace where our framework is also imported, running the demo-project is slow. When I import demo-project into empty eclipse workspace the bnd-run is really fast.
Sorry for confusion, the demo-project is of no use here - my fault!

I did some tests and successively deleted some of our framework's maven-projects from eclipse worspace and observed an increase of bnd-run speed.
Network seems not to be the problem, since I see same results without network connection.
Tim pointed out: "maven builds in Eclipse sometimes take a long time if the build dependency chain is very deep".
Indeed we do have (too) many dependencies and our framework does not make good use of OSGi services at all (yet).
But we do have interface- and impl-packages sepparated.

I will now follow Peters advice and first do little more observations:
1. "-runtrace=true" -> Did not know about this option. I will set this in my .bndrun and observe the results.
2. "disable build before launch" -> seems not to have any influence.
3. "enable logging of the builder" -> do you mean that I should set "Build Debug Logging" to full and then start eclipse in debug mode?

Thanks so far for your input.
I will investigate more and respond back.
Best regards,
Joerg

[Jörg Wille]

Speed problem issue is still not solved for us.

We are using bnd and bndtools 3.4-rc1 and Neon.3.

We are starting eclipse in debug mode as follows::
/Applications/Eclipse Neon.app/Contents/MacOS/eclipse -debug -consoleLog
and have set following key/values in a .options file:

org.eclipse.core.resources/debug=true
org.eclipse.core.resources/build/invoking=true
org.eclipse.core.resources/build/delta=true
org.eclipse.core.resources/build/needbuild=true
org.eclipse.core.resources/build/needbuildstack=false
org.eclipse.jdt.core/debug=true
org.eclipse.jdt.core/debug/builder=true
org.eclipse.jdt.core/debug/builder/stats= true
org.eclipse.core.runtime/debug=true
org.eclipse.m2e/debug=true
org.eclipse.m2e/debug/initialization=true
org.eclipse.m2e/debug/builder=true
org.eclipse.m2e/debug/projectManager=true

When we click the run button on a bndrun file, we are observing a delay of complete silence on the console.

This delay increases with the number of maven projects which we have in our workspace and with 50 and more projects in the workspace it is on some machines up to 20 seconds.
At this time in eclipse progress view it shows: "Launching : Build before launch - Performing required build..."
And the progress bar: "Launching tests.bndrun: (6%)"
But nothing seems to happen.

After this long delay of silence I do see fast output on the terminal, the console shows the -runtrace output and the application starts running very quickly.
I have attached a log file.

If there are changes in the code I still get the same delay of silence and then after 10-20 seconds, I see incremental builds taking place, as expected.

So the question is: what is eclipse doing in this long delay of silence?

- Are there any debug options for bnd/bndtools?
- Am I missing some other eclipse debug-oprions which would show what eclipse is doing?
- Can anyone tell me what eclipse is doing in this time?

Best regards,
Joerg

[Raymond Auge]

Could you maybe attach a couple (2 or 3) of thread dumps taken 1-3 seconds apart during this period of silence? It might help us identify the issue.

- Ray

To unsubscribe from this group and stop receiving emails from it, send an email to bndtools-users+unsubscribe@googlegroups.com.

[Jörg Wille]

Hey Ray,

thanks for your effort. Our integration tests as of today are time-consuming and therefore a little annoying.

We could try to split our maven-projects into different workspaces, but we could not get ourselves accustomed to often switch workspaces.

From the debug traces we see, that eclipse, m2e and bndtools are doing a lot under the hood to keep all projects in the workspace resolved, all files compiled and all bundles fresh and we understand that this conveniences do not come for free.
But to be precise, we are wondering what happens in the period in between we push "run" and before we see any logs of the necessary work in the terminal.
In the following picture we have drawn this period as a red line.

On some machines this "silent period" takes up to 20-30 seconds. The time does not change, if these machines are disconnected from the network. 

As requested I have attached the thread dumps taken 1 seconds apart and here is a link to a video showing this behaviour:

https://drive.google.com/open?id=0B-t-DI1vLmULSGNDa1M2UFh2STA

[Raymond Auge]

Thanks!

Can you clarify one more thing for me? Are you using bndtools workspace model?

Or are you using BNDTools m2e integration with maven projects using the bnd-maven-plugin?

- Ray

To unsubscribe from this group and stop receiving emails from it, send an email to bndtools-users+unsubscribe@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

Raymond Augé (@rotty3000)

Senior Software Architect Liferay, Inc. (@Liferay)

Board Member & EEG Co-Chair, OSGi Alliance (@OSGiAlliance)

[Jörg Wille]

We are using m2e integration with pure maven projects - no bnd-workspace.
I have given a link for a small test application in an earlier post in this thread:
https://github.com/joerg-wille/osgi-bnd-maven-example
We are using very similar maven bnd configurations in our real software.
But I am happy to share more insight into our setup - maybe we have made mistakes there.

- Joerg

[Raymond Auge]

On Wed, Jun 21, 2017 at 5:21 PM, Jörg Wille <joerg...@gmail.com> wrote:

We are using m2e integration with pure maven projects - no bnd-workspace.

Ok, I had missed that!

From what I can see here:

    at bndtools.m2e.MavenWorkspaceRepository.getMavenProject(MavenWorkspaceRepository.java:147)
    at bndtools.m2e.MavenWorkspaceRepository.init(MavenWorkspaceRepository.java:127)

MavenWorkspaceRepository is SUPER busy throughout all the thread dumps. It is definitely iterating over all the projects and seems to be building each one.

I wonder if the "built" state of each project is being properly detected!

I'll have to ask Greg if he's got any insight about this.

- Ray

 

To unsubscribe from this group and stop receiving emails from it, send an email to bndtools-users+unsubscribe@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

[Greg Amerson]

Hey guys,

I can take a look at the example repo and see what I can see.

G

Greg Amerson

Liferay Backend Developer Tools

Liferay, Inc. www.liferay.com

[Jörg Wille]

MavenWorkspaceRepository is SUPER busy throughout all the thread dumps. It is definitely iterating over all the projects and seems to be building each one.

I do not have any real understanding of the "MavenWorkspaceRepo", but I thought it has "only" a collecting job and would not "build" the projects.
Also, when we do have any code changes or we run for the first time, we do see log output from (incremental) builds in the debug terminal. But all building happens after the "silent period".
Are there any ".options" flags to enable tracing for MavenWorkspaceRepo or other bnd jobs?

- Joerg

[Jörg Wille]

Hey Greg,
Peter has already tried out the example and then we found out, that this example (by its own) runs fine, if the eclipse-workspace is not filled with hundreds of maven-projects of our framework. This example is of no use for speed debugging. But it does show, how we use and configured the bnd-(export-)maven-plugin.
As I mentioned before, deleting or closing a number of our framework's maven-projects from eclipse workspace does increase bnd-run speed.
But for our daily work we want as much of the maven-projects open in our workspace.

If you want to debug into our crowded workspace project, I can think of 2 possibilities:

- I can try to set up a public repo, with a test-project which uses our framework
- we can do a remote debug session

Thanks,
Joerg

[Greg Amerson]

Could you do a public git repo test project where you have created enough maven projects to cause this slow down when launching a bnd run file. 

Greg

[Jörg Wille]

Greg provided us with a test version of bndtools, where he has fixed something - maybe Greg wants to elaborate on the changes.

We have now extensively tested this test version on a couple of machines and we can confirm that our issue with a delayed start has now vanished.

No more "period of silence" before any necessary compiling starts or - in case of no code changes - before the bnd run starts.

So, thanks once more Greg for your support, we really appreciate this.

- Joerg

[Greg Amerson]

Thanks Joerg for verifying the fix.  I'll go ahead and merge the changes so they make it into 3.4.0-RC2

For those that are interested in the fix read on.... When you perform a "Bndtools run/debug" launch, just before the launch we inject a synthetic Maven workspace repository into the run/debug launch that covers all of the maven projects in the current Eclipse workspace.  This "maven workspace repository" was querying the m2e/maven project model for each project to determine the appropriate output bundle location.  The first time you query the maven project model this can be quite expensive (reading all poms in hierarchy, possibly downloading BOMs, etc).  If you do this same load over dozens of projects the "pause" in the launch can be very long as Joerg found out.  On a side not, I'm a bit puzzled by this as m2e should be caching the fully loaded maven project model so that subsequent loads should return quickly.  The first time would be slow, but subsequent times should be faster (unless there is some sort of cache miss in Joerg's case, I'm not clear here).  

Regardless, looking at the code again I realized in 99% of the time there is no need to do a full load of the m2e/maven project just to determine the output bundle location.  We can just "guess" based on a combination of $buildDirectory,  $artifactId and $version.  If we guess right, we can load the bundle immediately and skip the full maven project load.  For those 1% of cases (where the developer has customized something) we can always fallback to the full project load and we wont be any slower than before.

To unsubscribe from this group and stop receiving emails from it, send an email to bndtools-users+unsubscribe@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

[Milen Dyankov]

For those 1% of cases (where the developer has customized something) we can always fallback to the full project load and we wont be any slower than before.

How do you determine the developer has changed something? This can be changed by any plugin and / or extension.  Also there may be profiles or system properties that are applied, ... 

I'm not sure I understand what exactly you have done, but the word "guess" rings a bell immediately.

  

http://about.me/milen

[Greg Amerson]

If we don't find a valid bundle file in the guessed location then we load the full maven model (including profiles, systemproperties, etc) and we will find it.  This change just tries to short circuit this for the default case. Also, we have a hook (listener) into the m2e API that alerts us when the projects have changed (POMs have changed somewhere in project or update the hierarchy) and we will search for the bundle jar again (clear our cache).

But there is a chance of the following happening that would cause a problem.

1) user builds a bunch of projects all of the bundles are in the default location ${targetDirectory}/${artifactId}-${version}.jar

2) user launches a run/debug launch (our synthetic repo finds the default bundles)

3) user updates the maven model (profile or pom change) and bundles are now going to be built in a custom location

4) user rebuilds but doesn't first do a 'clean' so the old default jar is still in the default location

5) user relaunches run/debug, and now our synthetic repo will guess again but this time it will find the old stale default jars.

The workaround for this problem is the user does a clean build since then, the target directory will be clear and it won't find the old bundle jar at the default location.  So to avoid the chance of getting a stale jar we would need to think of a way of detecting the above situation without resorting to a full maven model load.  Thoughts?