Skip to content

Reduces check session and set context id redundant calls #1455

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 2 commits into from
Nov 28, 2017

Conversation

fredericDelaporte
Copy link
Member

@fredericDelaporte fredericDelaporte commented Nov 25, 2017

  • Reduces object allocations.

As noted in #1446, NHibernate checks are done many more time than required for a single overall operation. Session entry point methods should do the checks once and calls done from here up to the method end should not trigger them.

Two helper methods have been added on the abstract session impl: BeginProcess and BeginContext.
Both yields an IDisposable if we are not already in a "processing", otherwise they yield null. using supports this. This avoids allocating that small helper object when there is no work to do. The suspend auto flush helper has been changed accordingly (debatable, see review comment to come).
If not already processing, BeginProcess does check the status of the session, stores its id in context, then flag the session as "processing". BeginContext just stores its id in context if we are not already processing. BeginContext neither alters the processing flag, nor has a flag on its own (for simplicity).

For the session id context, skipping setting it again when it has already been set through an ongoing "processing" should not change anything to the feature (excepted its impact on perf): if, through some event or interceptor, it is changed by another session usage in such an event/interceptor while the first session is processing, its current logic will set back the first session id when ending the other session usage, which will forcibly occurs before the event or interceptor ends. (Unless an await on that other session is missing, but that would be a user bug even without this change.)

For the CheckAndUpdateSessionStatus status case, not running it again during a processing may weaken the error handling in case the user exploits an event or an interceptor to close the session or start a scope without completing it, while the session is "processing". I think it is acceptable. Closing the session during one of its event or interceptor call is clearly calling for troubles, so long for the user. Starting a scope outside of a using and inside an event or interceptor call is a bit exotic too.

CheckAndUpdateSessionStatus is still there and directly called in some cases (mainly properties access), and is now a no-op if the session is already "processing".
new SessionIdLoggingContext(sessionId) is now only directly called by AbstractSessionImpl and by the AdoTransaction which some methods may have to work without a session but with a stored session id.

BeginProcess and BeginContext are to be added to ISessionImplementor at some later point, but are now added as just extension methods of ISessionImplementor (avoiding a breaking change).

Many cases who were just setting the session id have been converted to BeginProcess, because they were calling some methods ending up doing that. In such case, better call BeginProcess the soonest, for reducing the most session id calls.
Some cases were pointlessly setting the id or checking the status, because their were doing nothing susceptible to log anything or actually do some processing, excepted calling a single method which was already doing the BeginProcess. (If it calls many methods doing it, then it should still call BeginProcess for achieving best savings.) They have been cleaned up of the call.
Some cases were calling the check status or were setting the id while being private and always called by methods doing it themselves. They have been cleaned up of the call.

@hazzik
Copy link
Member

hazzik commented Nov 25, 2017

The purpose of SessionIdLoggingContext was to log a session ID in a multythreaded environments, in a web app for example, where there can be many sessions simultaneously. I have not yet checked your implementation, but based on what I’ve read I’m not sure that it would work an that scenario.

@fredericDelaporte
Copy link
Member Author

fredericDelaporte commented Nov 25, 2017

It does change nothing to its working in such context. That purpose is supported by the usage of ThreadStatic (4.x impl)/AsyncLocal (5.0 & 5.0.1)/CallContext (your patch).
Setting it less frequently will not cause thread contamination.

@hazzik
Copy link
Member

hazzik commented Nov 25, 2017

@fredericDelaporte could you please add a multi-threaded concurrent version of NHibernate.Test.NHSpecificTest.Logs.Fixture.WillGetSessionIdFromSessionLogs? TextLogSpy should have a unique text pattern including the pre-set ID of that pattern. At assert it should check that all SessionIds logged are the same.

@@ -16,6 +16,20 @@

namespace NHibernate.Engine
{
// TODO: Convert to interface methods in 6.0
internal static class SessionImplementorExtensions
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We likely need a convention for ensuring not forgetting to convert back to plain methods "non-breaking change extension methods". I was thinking about obsoleting them immediately, but that would be confusing.

{
internal static IDisposable BeginContext(this ISessionImplementor session)
{
return (session as AbstractSessionImpl)?.BeginContext();
Copy link
Member Author

@fredericDelaporte fredericDelaporte Nov 25, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If we receive a custom implementation, currently choose to do nothing. For preserving the session id definition as it was even in case of a custom session, it could be changed by appending ?? new SessionIdLoggingContext(session.SessionId).

Update: done in an adjustment commit.


internal static IDisposable BeginProcess(this ISessionImplementor session)
{
return (session as AbstractSessionImpl)?.BeginProcess();
Copy link
Member Author

@fredericDelaporte fredericDelaporte Nov 25, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same as previous comment. All calls external to a session were only setting the context, but most were indeed calling things checking the status of the session, so they have been turned to a BeginProcess. So if we wish to handle a custom implementation in a way preserving the previous set session id, we can just yield here a SessionIdLoggingContext(sessionId) when encountering a custom implementation.

Update: done in an adjustment commit.

/// <summary> Cascade delete an entity instance</summary>
void Delete(string entityName, object child, bool isCascadeDeleteEnabled, ISet<object> transientEntities);

/// <summary>
/// Suspend auto-flushing, yielding a disposable to dispose when auto flush should be restored. Supports
/// being called multiple times.
/// </summary>
/// <returns>A disposable to dispose when auto flush should be restored.</returns>
/// <returns>A disposable to dispose when auto flush should be restored if it was not already suspended,
/// <see langword="null" /> otherwise.</returns>
IDisposable SuspendAutoFlush();
Copy link
Member Author

@fredericDelaporte fredericDelaporte Nov 25, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Here is the debatable change written about in the PR first comment. Here, a method which was never yielding null may now yield null. This is technically a breaking change. But I argue this method belongs to what Hibernate call "SPI", a "semi-private interface" here mainly for bearing internal needs. Moreover, the normal use of the return value of SuspendAutoFlush is with a using, which supports null, and there is then strictly nothing to do with the returned value.

Of course I can still revert this changes if it is preferred. (And granted, Hibernate does change SPI only on minor version changes, never on patch changes.)

Update: reverted in an adjustment commit.

@@ -54,7 +54,7 @@ public object PerformInsert(SqlCommandInfo insertSql, ISessionImplementor sessio
}

var selectSql = SelectSQL;
using (new SessionIdLoggingContext(session.SessionId))
using (session.BeginProcess())
Copy link
Member Author

@fredericDelaporte fredericDelaporte Nov 25, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Many accesses to Batcher are then done, which check the status. So better start immediately the BeginProcess rather than just storing the session id here. Many other similar changes are likewise, I will not comment them all.

@@ -366,7 +358,7 @@ public override FlushMode FlushMode

public override string BestGuessEntityName(object entity)
{
using (new SessionIdLoggingContext(SessionId))
using (BeginProcess())
Copy link
Member Author

@fredericDelaporte fredericDelaporte Nov 25, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Switch to BeginProcess for matching the method on SessionImpl side. Cannot be a breaking change because it is calling GuessEntityName which, in the case of the stateless session, was doing a status check for a mysterious reason.

Update: reverted in an adjustment commit, since the change on SessionImpl is reverted to.

@@ -379,8 +371,10 @@ public override string BestGuessEntityName(object entity)

public override string GuessEntityName(object entity)
{
CheckAndUpdateSessionStatus();
return entity.GetType().FullName;
using (BeginContext())
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Here that is the other way round: switching to BeginContext for matching the method on SessionImpl, and since what it does does not rely at all on the session state.

try
{
if(session.EnabledFilters.Count > 0)
{

// The above call validates the filters
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

And it is also checking the status, but that is now already done due to BeginProcess above instead of just setting the id.

@@ -309,7 +309,7 @@ protected virtual void Unlock()
/// <param name="preparingEnlistment">The object for notifying the prepare phase outcome.</param>
public virtual void Prepare(PreparingEnlistment preparingEnlistment)
{
using (new SessionIdLoggingContext(_session.SessionId))
using (_session.BeginContext())
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Due to the possibility of having already closed session, it must here call only BeginContext, even if in some case and depending on the configuration, it may do some later operation requiring an opened session. (Those operations will still do the check themselves.)

@@ -108,7 +108,7 @@ public void Begin()
/// </exception>
public void Begin(IsolationLevel isolationLevel)
{
using (new SessionIdLoggingContext(sessionId))
using (session.BeginProcess())
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Here using the stored session id is not useful, on Begin or Commit the ado transaction call only still have its session. And it must be opened.

@hazzik
Copy link
Member

hazzik commented Nov 25, 2017

Ok, I was trying to break this with following test:

[Test]
public void WillGetSessionIdFromSessionLogsConcurrent()
{
	GlobalContext.Properties["sessionId"] = new SessionIdCapturer();

	var semaphore = new ManualResetEventSlim();
	var array = Enumerable.Range(1, 10).Select(
		i => new Thread(
			() =>
			{
				using (var spy = new TextLogSpy("NHibernate.SQL", "%message | SessionId: %property{sessionId}"))
				using (var s = Sfi.OpenSession())
				{
					var sessionId = s.GetSessionImplementation().SessionId;
					semaphore.Wait();

					for (int j = 0; j < 10; j++)
					{
						s.Get<Person>(i * 10 + j); //will execute some sql
					}

					var loggingEvent = spy.GetWholeLog();
					for (int j = 0; j < 10; j++)
					{
						Assert.That(loggingEvent.Contains($"@p0 = {i * 10 + j} [Type: Int32 (0:0:0)] | SessionId: {sessionId}"), Is.True);
					}
				}
			})).ToArray();
	Array.ForEach(array, thread => thread.Start());
	semaphore.Set();
	Array.ForEach(array, thread => thread.Join());
}

It works.

@fredericDelaporte
Copy link
Member Author

With this PR, here are the changes in Frans benchmark, but run on my machine without a distant SQL Server contrary to what he recommends, for both runs of course. See #1446 for the issue triggering this PR.

Test NH v5.0.1 NH v5.0.1 altered by this PR % (base is unaltered 5.0.1)
Change tracking fetches, set fetches (50 runs), no caching 2.477,37ms, Enum: 1,59ms, 828.952KB 1.792,19ms, Enum: 1,63ms, 489.081KB -27.6%ms, Enum: +2.5%, -41%KB
Change tracking individual fetches (100 elements, 50 runs), no caching 0,42ms, 96KB 0,38ms, 80KB -9.5%ms, -16.6%KB
Change tracking fetches, eager load fetches, 3-node split graph, 1000 root elements (50 runs), no caching 381,94ms, 123.000KB 261,02ms, 62.672KB -31.7%ms, -49%KB

Thanks @hazzik for the additional test, I will add it.

@fredericDelaporte
Copy link
Member Author

fredericDelaporte commented Nov 25, 2017

While the table may be impressive, it should be noted that we have another kind of benchmark: our builds, running thousands of tests. No sensible changes here. But our tests are way more near "normal orm usage" than the benchmark.

@hazzik
Copy link
Member

hazzik commented Nov 25, 2017

@fredericDelaporte I think all "possible breaking changes" shall be reverted if we want to include this PR into 5.0.2.

@fredericDelaporte
Copy link
Member Author

fredericDelaporte commented Nov 25, 2017

The proposed test has some issues. Assert from spawned threads are not detected. The text log spy get logs from all threads and moreover does not seems to support it (they are seemingly truncated logs and missing logs). I am checking how to fix it.

Update: the text log spy was directly accessed from the spawned thread for getting its content, which was run concurrently to not yet finished threads still logging into it (all threads were logging to all spies), thus causing issues. Using only one text log spy for all threads and reading it after the threads have finished solves its troubles.

@fredericDelaporte
Copy link
Member Author

Table updated with a test run on this pr with latest commits.

Test NH v5.0.1 NH v5.0.1 altered by this PR, v2 % (base is unaltered 5.0.1)
Change tracking fetches, set fetches (50 runs), no caching 2.477,37ms, Enum: 1,59ms, 828.952KB 1.837,81ms, Enum: 1,53ms, 509.215KB -25,8%ms, Enum: -0,38%, -38,6%KB
Change tracking individual fetches (100 elements, 50 runs), no caching 0,42ms, 96KB 0,41ms, 80KB -2,4%ms, -16,6%KB
Change tracking fetches, eager load fetches, 3-node split graph, 1000 root elements (50 runs), no caching 381,94ms, 123.000KB 254,74ms, 66.960KB -33,3%ms, -45,6%KB

@fredericDelaporte
Copy link
Member Author

fredericDelaporte commented Nov 25, 2017

I have checked if #1453 or #1391 still give significant gains by applying them above this PR (in fact, by removing all code from the session context for simulating #1391).

Here are the results.

Test NH v5.0.1 NH v5.0.1 altered by this PR, v2 + #1453 % (base is unaltered 5.0.1)
Change tracking fetches, set fetches (50 runs), no caching 2.477,37ms, Enum: 1,59ms, 828.952KB 1.770,55ms, Enum: 1,65ms, 490.488KB -28,5%ms, Enum: +3,8%, -40,8%KB
Change tracking individual fetches (100 elements, 50 runs), no caching 0,42ms, 96KB 0,35ms, 72KB -16,6%ms, -25%KB
Change tracking fetches, eager load fetches, 3-node split graph, 1000 root elements (50 runs), no caching 381,94ms, 123.000KB 246,8ms, 62.992KB -35,4%ms, -48,8%KB
Test NH v5.0.1 NH v5.0.1 altered by this PR, v2 + #1391 % (base is unaltered 5.0.1)
Change tracking fetches, set fetches (50 runs), no caching 2.477,37ms, Enum: 1,59ms, 828.952KB 1.716,01ms, Enum: 1,55ms, 489.783KB -30,8%ms, Enum: -2,5%, -40,9%KB
Change tracking individual fetches (100 elements, 50 runs), no caching 0,42ms, 96KB 0,34ms, 72KB -19%ms, -25%KB
Change tracking fetches, eager load fetches, 3-node split graph, 1000 root elements (50 runs), no caching 381,94ms, 123.000KB 250,09ms, 62.832KB -34,5%ms, -48,9%KB

So, for comparing them all:

Test NH v5.0.1 altered by this PR, v2 NH v5.0.1 altered by this PR, v2 + #1453 NH v5.0.1 altered by this PR, v2 + #1391
Change tracking fetches, set fetches (50 runs), no caching -25,8%ms, Enum: -0,38%, -38,6%KB -28,5%ms, Enum: +3,8%, -40,8%KB -30,8%ms, Enum: -2,5%, -40,9%KB
Change tracking individual fetches (100 elements, 50 runs), no caching -2,4%ms, -16,6%KB -16,6%ms, -25%KB -19%ms, -25%KB
Change tracking fetches, eager load fetches, 3-node split graph, 1000 root elements (50 runs), no caching -33,3%ms, -45,6%KB -35,4%ms, -48,8%KB -34,5%ms, -48,9%KB

Differences between this PR + #1453 and this PR + #1391 are quite minimal. (My first #1391 run was even worst on all tests so I have just guessed that some background process has interfered and I have done another run.) So I do not think we need to do both if the PR here is merged. Since #1391 will be useful for a .Net Standard version too, I would favor just keeping #1391. This would avoid introducing code depending on the target framework.

@hazzik
Copy link
Member

hazzik commented Nov 25, 2017

Differences between this PR + #1453 and this PR + #1391 are quite minimal. [...] So I do not think we need to do both if the PR here is merged. Since #1391 will be useful for a .Net Standard version too, I would favor just keeping #1391. This would avoid introducing code depending on the target framework.

Don’t forget, that #1391 is just an option to disable the session tracking. If session tracking is enabled (or in .netstandard) you still get reduced performance (as pointed by a table with “bare” tests of this PR). So we need to keep a combined solution.

The proposed test is not correct.

It was a really quick test.

@fredericDelaporte
Copy link
Member Author

fredericDelaporte commented Nov 25, 2017

Is should have formulated it another way, I was just willing to let know that is was not yet validating multi-threaded usage but that I was looking into it.

Why not combined all them too if you thinks its better. #1391 is already in master and #1453 is not a lot of code. #1455 impacts more code but render it a bit cleaner by the way, avoiding the dual "set id & check status" calls that were common place all around.

@hazzik
Copy link
Member

hazzik commented Nov 26, 2017

@fredericDelaporte can you please also add a test when there are several parallel sessions in the same thread?

@hazzik
Copy link
Member

hazzik commented Nov 26, 2017

Also, need to rewrite an async version of the test(s) to be more async-ish (eg using Tasks instead of Threads).

@fredericDelaporte
Copy link
Member Author

Rebased, squashed and done.

{
if (i > 10)
{
// Give some time to threads for reaching the wait, having all of them ready to do most of their job concurrently.
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I have changed the thread array to a Parallel.For for exploiting maca88/AsyncGenerator#63. But since Parallel.For is blocking, this forbids releasing the semaphore afterward. So I have added the releasing as the last process in the Parallel.For. Since upper bound is excluded, it then needs to be twelve, for having ten threads and an eleventh one releasing them all.
The test for detecting we are the elventh one is i > 10 instead of i == 11 for avoiding having an issue in the async counterpart due to maca88/AsyncGenerator#72. Better release "more than needed" the semaphore than waiting too much on it.

Copy link
Member Author

@fredericDelaporte fredericDelaporte Nov 27, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Maca has already fixed it but we are on a branch which is still using the 0.6.0 version, not the 0.6.2 version. Upgrading it here to 0.6.3 would cause many additional changes. So I will leave it as is in this PR.

protected override void Configure(Configuration configuration)
{
base.Configure(configuration);
configuration.SetProperty(Cfg.Environment.UseSecondLevelCache, "false");
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

TestCase base class causes all entities to be cacheable in second level cache by default, and enables it. Quite tricky for a test which relies on emitted SQL.

@fredericDelaporte
Copy link
Member Author

fredericDelaporte commented Nov 28, 2017

For completing the comparison, here the table with 5.0.x branch current state (so with #1453 merged in):

Test NH v5.0.1 NH v5.0.1 + #1453 % (base is unaltered 5.0.1)
Change tracking fetches, set fetches (50 runs), no caching 2.477,37ms, Enum: 1,59ms, 828.952KB 2.037,07ms, Enum: 1,63ms, 514.175KB -17,8%ms, Enum: +2,5%, -38%KB
Change tracking individual fetches (100 elements, 50 runs), no caching 0,42ms, 96KB 0,38ms, 80KB -9,5%ms, -16,6%KB
Change tracking fetches, eager load fetches, 3-node split graph, 1000 root elements (50 runs), no caching 381,94ms, 123.000KB 312,61ms, 67.142KB -18,2%ms, -44,4%KB

Overall comparison:

Test NH v5.0.1 + #1453 NH v5.0.1 altered by this PR, v2 NH v5.0.1 altered by this PR, v2 + #1453 NH v5.0.1 altered by this PR, v2 + #1391
Change tracking fetches, set fetches (50 runs), no caching -17,8%ms, Enum: +2,5%, -38%KB -25,8%ms, Enum: -0,38%, -38,6%KB -28,5%ms, Enum: +3,8%, -40,8%KB -30,8%ms, Enum: -2,5%, -40,9%KB
Change tracking individual fetches (100 elements, 50 runs), no caching -9,5%ms, -16,6%KB -2,4%ms, -16,6%KB -16,6%ms, -25%KB -19%ms, -25%KB
Change tracking fetches, eager load fetches, 3-node split graph, 1000 root elements (50 runs), no caching -18,2%ms, -44,4%KB -33,3%ms, -45,6%KB -35,4%ms, -48,8%KB -34,5%ms, -48,9%KB

@fredericDelaporte fredericDelaporte merged commit b40526d into nhibernate:5.0.x Nov 28, 2017
@fredericDelaporte fredericDelaporte deleted the sessionProcess branch November 28, 2017 11:55
@fredericDelaporte fredericDelaporte added this to the 5.0.2 milestone Nov 28, 2017
@hazzik
Copy link
Member

hazzik commented Nov 28, 2017

@fredericDelaporte could you please make a final comparison of 5.0.1 and the current state of the branch?

@hazzik hazzik mentioned this pull request Nov 28, 2017
@fredericDelaporte
Copy link
Member Author

That is "NH v5.0.1 altered by this PR, v2 + #1453". But well, just in case, I have re-run it on my 5.0.2 branch (the one for the release PR).

Test NH v5.0.1 NH v5.0.2 % (base is unaltered 5.0.1)
Change tracking fetches, set fetches (50 runs), no caching 2.477,37ms, Enum: 1,59ms, 828.952KB 1.726,01ms, Enum: 1,54ms, 490.487KB -30,3%ms, Enum: -5%, -40.8%KB
Change tracking individual fetches (100 elements, 50 runs), no caching 0,42ms, 96KB 0,36ms, 72KB -14,3%ms, -25%KB
Change tracking fetches, eager load fetches, 3-node split graph, 1000 root elements (50 runs), no caching 381,94ms, 123.000KB 247,76ms, 62.992KB -35,1%ms, -48,8%KB

So, no significant changes compared to "NH v5.0.1 altered by this PR, v2 + #1453", all are below the standard deviation reported in the bench logs.

I have updated the tables of the previous comment: I had taken data from the async benchmark by error for the third line.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants