Bug 64400 - if transaction names starts identically, jmeter puts it in the same transaction controller during recording
Summary: if transaction names starts identically, jmeter puts it in the same transacti...
Status: RESOLVED FIXED
Alias: None
Product: JMeter
Classification: Unclassified
Component: HTTP (show other bugs)
Version: Nightly (Please specify date)
Hardware: All All
: P2 normal (vote)
Target Milestone: JMETER_5.3.0
Assignee: JMeter issues mailing list
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2020-04-30 14:47 UTC by Alex Podelko
Modified: 2020-05-28 14:16 UTC (History)
0 users



Attachments
screenshot with recording outcome (237.53 KB, image/jpeg)
2020-04-30 14:47 UTC, Alex Podelko
Details
the script illustrating the issue (436.91 KB, application/xml)
2020-04-30 17:34 UTC, Alex Podelko
Details
the real script I recorded (254.16 KB, application/x-zip-compressed)
2020-05-03 02:56 UTC, Alex Podelko
Details
Sorting into transaction groups without problem (137.63 KB, image/png)
2020-05-03 08:25 UTC, Felix Schumacher
Details
Possible race condition when placing samplers (12.00 KB, patch)
2020-05-03 11:34 UTC, Felix Schumacher
Details | Diff
script recorded with new nightly build - looks good (25.60 KB, application/x-zip-compressed)
2020-05-07 01:09 UTC, Alex Podelko
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Alex Podelko 2020-04-30 14:47:15 UTC
Created attachment 37208 [details]
screenshot with recording outcome

If transaction names starts identically, jmeter puts it in the same transaction controller during recording.

For example, I had transaction names as '1M request new', '1M request1 1k parse', '1M request 1k load', '1M request 1k validate', etc. - it put all of them into the single transaction controller '1M request new'. See the screenshot.

My guess it is when the transaction name starts identically - but it some cases it still breaks it between several transaction controllers (sometimes with the same name)...

[JMeter 5.3-SNAPSHOT d652f1c]
Comment 1 Felix Schumacher 2020-04-30 15:04:31 UTC
Hi Alex,

can you post a minimal test plan that reproduces the issue?
Comment 2 Alex Podelko 2020-04-30 17:34:03 UTC
Created attachment 37210 [details]
the script illustrating the issue

recorded the script against google - opening a home page and running three searches, all in different transactions:
google home
google search 1
google search 2
google search 3

however everything got recorded under the 'google home' transaction controller (while individual HTTP requests got the proper prefix)
Comment 3 Felix Schumacher 2020-05-02 16:33:12 UTC
I tested a recording session myself with transaction names 'transaction one', 'transaction two' and 'transaction three'. I recorded three samples and all went into the correct transaction.

Did you try latest nightly (though I didn't see any relevant commits from your version to the current one)?

How long did you wait between changing the transaction name and recording the samples?

Which version of OS and JVM did you use?

Did you see any errors in jmeter.log?
Comment 4 Antonio Gomes Rodrigues 2020-05-02 19:37:56 UTC
Hi

Do you have modified this line in jmeter.properties

# If the recorder detects a gap of at least 5s (default) between HTTP requests,
# it assumes that the user has clicked a new URL
#proxy.pause=5000

Or the option "Create new transaction after request" in HTTP(S) Test Script Recorder ?

Antonio
Comment 5 Alex Podelko 2020-05-03 02:51:23 UTC
Here is the machine info from JMeter log:

2020-05-01 14:56:52,073 INFO o.a.j.JMeter: Version 5.3-SNAPSHOT d652f1c
2020-05-01 14:56:52,073 INFO o.a.j.JMeter: java.version=1.8.0_251
2020-05-01 14:56:52,073 INFO o.a.j.JMeter: java.vm.name=Java HotSpot(TM) 64-Bit Server VM
2020-05-01 14:56:52,073 INFO o.a.j.JMeter: os.name=Windows Server 2012 R2
2020-05-01 14:56:52,073 INFO o.a.j.JMeter: os.arch=amd64
2020-05-01 14:56:52,073 INFO o.a.j.JMeter: os.version=6.3
2020-05-01 14:56:52,073 INFO o.a.j.JMeter: file.encoding=Cp1252
2020-05-01 14:56:52,073 INFO o.a.j.JMeter: java.awt.headless=null
2020-05-01 14:56:52,073 INFO o.a.j.JMeter: Max memory     =1073741824
2020-05-01 14:56:52,073 INFO o.a.j.JMeter: Available Processors =8
2020-05-01 14:56:52,089 INFO o.a.j.JMeter: Default Locale=English (EN)
2020-05-01 14:56:52,089 INFO o.a.j.JMeter: JMeter  Locale=English (EN)
2020-05-01 14:56:52,089 INFO o.a.j.JMeter: JMeterHome=C:\apache-jmeter-5.3-SNAPSHOT
2020-05-01 14:56:52,089 INFO o.a.j.JMeter: user.dir  =c:\JMeter_Scripts

I haven't changed anything in recording settings, all should be default.

It is not that it records everything in one transaction controllers - for transaction with different names it worked fine. Only transactions starting similarly got together - see '1m request...' and '200k request...' in the actual script attached.

Another interesting issue is that it broke it into several different transaction controllers in other places and it doesn't looks like it is time-based (some short got broken and some long didn't). That it is another issue, just mentioning here.
Comment 6 Alex Podelko 2020-05-03 02:56:30 UTC
Created attachment 37213 [details]
the real script I recorded
Comment 7 Alex Podelko 2020-05-03 03:01:35 UTC
See the real script I recorded. See "1M request new" and "200K request new" to see the issue. Still you may see that pattern is not completely clear - '200 request100 validate', vice versa, got broken into multiple transaction controllers while it was a rather short transaction.
Comment 8 Felix Schumacher 2020-05-03 08:25:01 UTC
Created attachment 37215 [details]
Sorting into transaction groups without problem

Hi Alex, I attach a picture of a recorded script, that seems correct to me. I used the names of the transactions you mentioned and used curl to trigger the samples. All samples are stored in the correct transactions (the first transaction is split into two, as I waited too long between the samples).
Comment 9 Felix Schumacher 2020-05-03 08:32:44 UTC
Did you see the behaviour with short recordings, too?

How fast were the original requests recorded/triggered? Were they done concurrently (My test was sequential, only)?

How much time does it take you to switch the transaction names?

Where do you switch the names (I did it in the popup window)?
Comment 10 Felix Schumacher 2020-05-03 11:34:53 UTC
Created attachment 37216 [details]
Possible race condition when placing samplers

Alex, I think the problems arise from a race condition inside the placement code for the recorded samples. I tried to extract the logic to be less prone to this race condition. Could you try the patch with your setup?

There is at least one place, where we still are not 100 % thread safe. That is in ProxyControl#deliverSample when we compute the target node 'myTarget'. That happens outside the Swing Thread and thus could result in the wrong target, too.

To get a wrong result with the current code base, you have to be fast (changing the name of the transaction controller) and have a lot of concurrent (or near concurrent) requests. I used a shell command 'for i in $(seq 200); do curl http://targethost & done; wait'
Comment 11 Alex Podelko 2020-05-03 18:28:49 UTC
Your recording looks fine indeed. 

As you may see from attached 'the script illustrating the issue', I reproduced the same problem with a very short script recorded with Google search (so it shouldn't be related to my specific system).

It was just standard recording - I type in a transaction name into pop up window (I actually am not aware about any other methods), click on something, wait until it finishes, change the name for the next transaction. Nothing quick - some transaction takes more than a minute and I am not a quick typist. Clicking some actions may invoke some requests in parallel in the background - but it is the only concurrency I can think about.

The only interesting specific of my environment is that I am doing it on a server (VM) with 8 CPUs... Not sure how it may be connected, but sometimes it creates really amusing effects.

One more thing comes to mind that I haven't replaced the whole name - just changed the ending of the transaction...

Thanks,
Alex
Comment 12 Felix Schumacher 2020-05-04 10:16:42 UTC
(In reply to Alex Podelko from comment #11)
> Your recording looks fine indeed. 

It does, as I let enough time pass between changing the name of the transaction and recording the next samples.

> 
> As you may see from attached 'the script illustrating the issue', I
> reproduced the same problem with a very short script recorded with Google
> search (so it shouldn't be related to my specific system).

The problem can be seen, when you record samples shortly after changing the transaction name. JMeter doesn't take the name of the transaction into account, when it decides if it should create a new controller. I only looks at the time of the last sample.

The default gap time seems to be 5 seconds.

> 
> It was just standard recording - I type in a transaction name into pop up
> window (I actually am not aware about any other methods), click on
> something, wait until it finishes, change the name for the next transaction.
> Nothing quick - some transaction takes more than a minute and I am not a
> quick typist. Clicking some actions may invoke some requests in parallel in
> the background - but it is the only concurrency I can think about.
> 
> The only interesting specific of my environment is that I am doing it on a
> server (VM) with 8 CPUs... Not sure how it may be connected, but sometimes
> it creates really amusing effects.
> 
> One more thing comes to mind that I haven't replaced the whole name - just
> changed the ending of the transaction...

Can you try out the patch I attached? If not, I would submit it to trunk and you could try out next nightly.


> 
> Thanks,
> Alex
Comment 13 Alex Podelko 2020-05-04 14:56:09 UTC
>The problem can be seen, when you record samples shortly after changing the >transaction name. JMeter doesn't take the name of the transaction into account, >when it decides if it should create a new controller. I only looks at the time of >the last sample.

>The default gap time seems to be 5 seconds.

Hmm... Didn't realized that... Well, then it may be working here as designed.

I indeed may record the google script faster than 5 sec - if I wait longer, it put requests into different transactions.

With my product, it is more interesting. When a 'request' (think a 'form' here) is open, it polls the server each 4 seconds. So it never could be a case when we have 5+ sec between HTTP requests - so they all got into one transaction controller.

Then the more interesting question would be how '200k request *' got broken into multiple transaction controllers - when we still have /epm/ui-rest/v1/changeEvents invoked every 4 sec.

[Another question is why would we break it by time if we specify transaction names - if somebody cares to specify transaction names, I can't come with the case why he may be interested to break it not according to specified name. Any thoughts?]
Comment 14 Felix Schumacher 2020-05-04 15:20:02 UTC
Hi Alex,

I committed the patch, that splits the transaction on time or prefix (plus a bit of rework, to make insertion of the samples a bit more predictable).

Can you test with the next build?


commit cee4de981d0165416a0d1783ac5ced84531d47a5
AuthorDate: Sun May 3 10:56:59 2020 +0200

    Update JMeterTreeModel in a threadsafe and timely manner
    
    When recording multiple samples concurrently, we could get into a race
    condition and place samples into wrong controllers.
    
    Now we try to get the current information about prefix and sampler as soon as possible
    and delay the addition of the sampler to the recording controller by means of a queue.
---
 .../jmeter/protocol/http/proxy/ProxyControl.java   | 190 +++++++++++++--------
 xdocs/changes.xml                                  |   1 +
 2 files changed, 120 insertions(+), 71 deletions(-)
Comment 15 Felix Schumacher 2020-05-06 10:59:20 UTC
commit 20d3535cc0360c9ff539836973daea624ace62bf
AuthorDate: Wed May 6 12:51:30 2020 +0200

    Only process events in timer, when proxy recorded samplers
    
    Otherwise we get errors, when the Tree model is not
    initialized correctly in ProxyControl instances.
    The logic with this change is, that at the stage, when
    proxy recorded smaplers, the instance has to be set up
    correctly
    
    Follow-up to cee4de981d0165416a0d1783ac5ced84531d47a5
    Bugzilla Id: 64400
---
 .../main/java/org/apache/jmeter/protocol/http/proxy/ProxyControl.java | 4 ++++
 1 file changed, 4 insertions(+)
Comment 16 Alex Podelko 2020-05-07 01:09:16 UTC
Created attachment 37218 [details]
script recorded with new nightly build - looks good
Comment 17 Alex Podelko 2020-05-07 01:10:45 UTC
See the attached script recorded with a new nightly build (200505). Looks good - don't see that problem anymore.