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

Npgsql needlessly prepare transactions in some cases #1625

Open
fredericDelaporte opened this Issue Jun 28, 2017 · 6 comments

Comments

Projects
None yet
3 participants
@fredericDelaporte
Contributor

fredericDelaporte commented Jun 28, 2017

When a Npgsql connection is used in a system transaction along with another volatile resource manager not supporting single phase commit, the system transaction remains not distributed. But the Npgsql resource manager get called with 2PC, causing it to prepare the transaction instead, as if it was distributed.

Current Npgsql resource manager implementation is a volatile resource manager supporting single phase commit.
Using a durable resource supporting single phase commit here would avoid that unneeded prepare. When a single durable resource is enlisted in a transaction and supports single phase commit, its single phase commit is called even if there are volatile resources enlisted which do not support single phase. But this optimization does not happen for volatile resource, which Npgsql currently is.

Steps to reproduce

(Full class with more tests could be seen here.)

using System;
using System.Threading;
using System.Transactions;
using log4net;
using log4net.Repository.Hierarchy;
using NUnit.Framework;

using SysTran = System.Transactions.Transaction;

namespace Test.SystemTransactions
{
	/// <summary>
	/// Holds tests for checking MSDTC resource managers behavior.
	/// </summary>
	public class ResourceManagerFixture
	{
		private static readonly ILog _log = LogManager.GetLogger(typeof(ResourceManagerFixture));

		[OneTimeSetUp]
		public void TestFixtureSetUp()
		{
			((Logger)_log.Logger).Level = log4net.Core.Level.Info;
		}

		[SetUp]
		public void SetUp()
		{
			EnlistResource.Counter = 0;
		}

		[Test]
		public void NonDistributedCommit()
		{
			using (var scope = new TransactionScope())
			{
				_log.InfoFormat("Scope opened, id {0}, distributed id {1}",
					SysTran.Current.TransactionInformation.LocalIdentifier,
					SysTran.Current.TransactionInformation.DistributedIdentifier);
				// Simulate a simple connection: durable resource supporting single phase.
				// (Note that SQL Server 2005 and above use IPromotableSinglePhaseNotification
				// for delegating the resource management to the SQL server.)
				EnlistResource.EnlistDurable(false, true);
				_log.InfoFormat("Fake connection opened, scope id {0} and distributed id {1}",
					SysTran.Current.TransactionInformation.LocalIdentifier,
					SysTran.Current.TransactionInformation.DistributedIdentifier);
				// Simulate NHibernate : volatile no single phase support
				EnlistResource.EnlistVolatile();
				_log.InfoFormat("Fake session opened, scope id {0} and distributed id {1}",
					SysTran.Current.TransactionInformation.LocalIdentifier,
					SysTran.Current.TransactionInformation.DistributedIdentifier);
				scope.Complete();
				_log.Info("Scope completed");
			}
			_log.Info("Scope disposed");
		}

		[Test]
		public void NonDistributedNpgsqlCommit()
		{
			using (var scope = new TransactionScope())
			{
				_log.InfoFormat("Scope opened, id {0}, distributed id {1}",
					SysTran.Current.TransactionInformation.LocalIdentifier,
					SysTran.Current.TransactionInformation.DistributedIdentifier);
				// Simulate a Npgsql connection: as of Npgsql 3.2.4, volatile resource with single phase support
				EnlistResource.EnlistVolatile(false, true);
				_log.InfoFormat("Fake connection opened, scope id {0} and distributed id {1}",
					SysTran.Current.TransactionInformation.LocalIdentifier,
					SysTran.Current.TransactionInformation.DistributedIdentifier);
				// Simulate NHibernate : volatile no single phase support
				EnlistResource.EnlistVolatile();
				_log.InfoFormat("Fake session opened, scope id {0} and distributed id {1}",
					SysTran.Current.TransactionInformation.LocalIdentifier,
					SysTran.Current.TransactionInformation.DistributedIdentifier);
				scope.Complete();
				_log.Info("Scope completed");
			}
			_log.Info("Scope disposed");
		}

		public class EnlistResource : IEnlistmentNotification
		{
			public static int SleepTime { get; set; } = 2;
			public static int Counter { get; set; }

			protected bool ShouldRollBack { get; }
			protected string Name { get; }

			public static void EnlistVolatile(bool shouldRollBack = false)
				=> EnlistVolatile(shouldRollBack, false);

			public static void EnlistVolatile(bool shouldRollBack, bool supportsSinglePhase)
				=> Enlist(false, supportsSinglePhase, shouldRollBack);

			public static void EnlistDurable(bool shouldRollBack = false)
				=> EnlistDurable(shouldRollBack, false);

			public static void EnlistDurable(bool shouldRollBack, bool supportsSinglePhase)
				=> Enlist(true, supportsSinglePhase, shouldRollBack);

			private static void Enlist(bool durable, bool supportsSinglePhase, bool shouldRollBack)
			{
				Counter++;

				var name = $"{(durable ? "Durable" : "Volatile")} resource {Counter}";
				EnlistResource resource;
				if (supportsSinglePhase)
				{
					var spResource = new EnlistSinglePhaseResource(shouldRollBack, name);
					resource = spResource;
					if (durable)
						SysTran.Current.EnlistDurable(Guid.NewGuid(), spResource, EnlistmentOptions.None);
					else
						SysTran.Current.EnlistVolatile(spResource, EnlistmentOptions.None);
				}
				else
				{
					resource = new EnlistResource(shouldRollBack, name);
					// Not duplicate code with above, that is not the same overload which ends up called.
					if (durable)
						SysTran.Current.EnlistDurable(Guid.NewGuid(), resource, EnlistmentOptions.None);
					else
						SysTran.Current.EnlistVolatile(resource, EnlistmentOptions.None);
				}

				SysTran.Current.TransactionCompleted += resource.Current_TransactionCompleted;

				_log.Info(name + ": enlisted");
			}

			protected EnlistResource(bool shouldRollBack, string name)
			{
				ShouldRollBack = shouldRollBack;
				Name = name;
			}

			public void Prepare(PreparingEnlistment preparingEnlistment)
			{
				_log.Info(Name + ": prepare phase start");
				Thread.Sleep(SleepTime);
				if (ShouldRollBack)
				{
					_log.Info(Name + ": prepare phase, calling rollback-ed");
					preparingEnlistment.ForceRollback();
				}
				else
				{
					_log.Info(Name + ": prepare phase, calling prepared");
					preparingEnlistment.Prepared();
				}
				Thread.Sleep(SleepTime);
				_log.Info(Name + ": prepare phase end");
			}

			public void Commit(Enlistment enlistment)
			{
				_log.Info(Name + ": commit phase start");
				Thread.Sleep(SleepTime);
				_log.Info(Name + ": commit phase, calling done");
				enlistment.Done();
				Thread.Sleep(SleepTime);
				_log.Info(Name + ": commit phase end");
			}

			public void Rollback(Enlistment enlistment)
			{
				_log.Info(Name + ": rollback phase start");
				Thread.Sleep(SleepTime);
				_log.Info(Name + ": rollback phase, calling done");
				enlistment.Done();
				Thread.Sleep(SleepTime);
				_log.Info(Name + ": rollback phase end");
			}

			public void InDoubt(Enlistment enlistment)
			{
				_log.Info(Name + ": in-doubt phase start");
				Thread.Sleep(SleepTime);
				_log.Info(Name + ": in-doubt phase, calling done");
				enlistment.Done();
				Thread.Sleep(SleepTime);
				_log.Info(Name + ": in-doubt phase end");
			}

			private void Current_TransactionCompleted(object sender, TransactionEventArgs e)
			{
				_log.Info(Name + ": transaction completed start");
				Thread.Sleep(SleepTime);
				_log.Info(Name + ": transaction completed middle");
				Thread.Sleep(SleepTime);
				_log.Info(Name + ": transaction completed end");
			}

			private class EnlistSinglePhaseResource : EnlistResource, ISinglePhaseNotification
			{
				public EnlistSinglePhaseResource(bool shouldRollBack, string name) :
					base(shouldRollBack, "Single phase " + name)
				{
				}

				public void SinglePhaseCommit(SinglePhaseEnlistment singlePhaseEnlistment)
				{
					_log.Info(Name + ": transaction single phase start");
					Thread.Sleep(SleepTime);
					if (ShouldRollBack)
					{
						_log.Info(Name + ": transaction single phase, calling aborted");
						singlePhaseEnlistment.Aborted();
					}
					else
					{
						_log.Info(Name + ": transaction single phase, calling committed");
						singlePhaseEnlistment.Committed();
					}
					Thread.Sleep(SleepTime);
					_log.Info(Name + ": transaction single phase end");
				}
			}
		}
	}
}

The logs for NonDistributedCommit are:

19:17:28,896 INFO  ResourceManagerFixture:37 - Scope opened, id 6b74953e-f109-4c2f-b58f-44cd0776e348:1, distributed id 00000000-0000-0000-0000-000000000000
19:17:28,947 INFO  ResourceManagerFixture:129 - Durable resource 1: enlisted
19:17:28,948 INFO  ResourceManagerFixture:44 - Fake connection opened, scope id 6b74953e-f109-4c2f-b58f-44cd0776e348:1 and distributed id 00000000-0000-0000-0000-000000000000
19:17:28,951 INFO  ResourceManagerFixture:129 - Volatile resource 2: enlisted
19:17:28,951 INFO  ResourceManagerFixture:49 - Fake session opened, scope id 6b74953e-f109-4c2f-b58f-44cd0776e348:1 and distributed id 00000000-0000-0000-0000-000000000000
19:17:28,951 INFO  ResourceManagerFixture:53 - Scope completed
19:17:28,960 INFO  ResourceManagerFixture:140 - Volatile resource 2: prepare phase start
19:17:28,964 INFO  ResourceManagerFixture:149 - Volatile resource 2: prepare phase, calling prepared
19:17:28,968 INFO  ResourceManagerFixture:204 - Single phase Durable resource 1: transaction single phase start
19:17:28,971 INFO  ResourceManagerFixture:213 - Single phase Durable resource 1: transaction single phase, calling committed
19:17:28,974 INFO  ResourceManagerFixture:158 - Volatile resource 2: commit phase start
19:17:28,978 INFO  ResourceManagerFixture:160 - Volatile resource 2: commit phase, calling done
19:17:28,982 INFO  ResourceManagerFixture:163 - Volatile resource 2: commit phase end
19:17:28,982 INFO  ResourceManagerFixture:188 - Single phase Durable resource 1: transaction completed start
19:17:28,986 INFO  ResourceManagerFixture:190 - Single phase Durable resource 1: transaction completed middle
19:17:28,989 INFO  ResourceManagerFixture:192 - Single phase Durable resource 1: transaction completed end
19:17:28,989 INFO  ResourceManagerFixture:188 - Volatile resource 2: transaction completed start
19:17:28,992 INFO  ResourceManagerFixture:190 - Volatile resource 2: transaction completed middle
19:17:28,995 INFO  ResourceManagerFixture:192 - Volatile resource 2: transaction completed end
19:17:28,998 INFO  ResourceManagerFixture:217 - Single phase Durable resource 1: transaction single phase end
19:17:29,001 INFO  ResourceManagerFixture:153 - Volatile resource 2: prepare phase end
19:17:29,005 INFO  ResourceManagerFixture:55 - Scope disposed

In presence of a single durable resource with single phase commit manager, with some volatile resource manager, the system first prepare volatile resource, then perform the durable single phase, then perform the volatile second phase. So the durable resource has worked with its single phase.

The logs for NonDistributedNpgsqlCommit are:

19:17:29,026 INFO  ResourceManagerFixture:63 - Scope opened, id 6b74953e-f109-4c2f-b58f-44cd0776e348:2, distributed id 00000000-0000-0000-0000-000000000000
19:17:29,028 INFO  ResourceManagerFixture:129 - Volatile resource 1: enlisted
19:17:29,028 INFO  ResourceManagerFixture:68 - Fake connection opened, scope id 6b74953e-f109-4c2f-b58f-44cd0776e348:2 and distributed id 00000000-0000-0000-0000-000000000000
19:17:29,028 INFO  ResourceManagerFixture:129 - Volatile resource 2: enlisted
19:17:29,028 INFO  ResourceManagerFixture:73 - Fake session opened, scope id 6b74953e-f109-4c2f-b58f-44cd0776e348:2 and distributed id 00000000-0000-0000-0000-000000000000
19:17:29,029 INFO  ResourceManagerFixture:77 - Scope completed
19:17:29,029 INFO  ResourceManagerFixture:140 - Single phase Volatile resource 1: prepare phase start
19:17:29,032 INFO  ResourceManagerFixture:149 - Single phase Volatile resource 1: prepare phase, calling prepared
19:17:29,035 INFO  ResourceManagerFixture:153 - Single phase Volatile resource 1: prepare phase end
19:17:29,035 INFO  ResourceManagerFixture:140 - Volatile resource 2: prepare phase start
19:17:29,038 INFO  ResourceManagerFixture:149 - Volatile resource 2: prepare phase, calling prepared
19:17:29,038 INFO  ResourceManagerFixture:158 - Single phase Volatile resource 1: commit phase start
19:17:29,041 INFO  ResourceManagerFixture:160 - Single phase Volatile resource 1: commit phase, calling done
19:17:29,044 INFO  ResourceManagerFixture:163 - Single phase Volatile resource 1: commit phase end
19:17:29,044 INFO  ResourceManagerFixture:158 - Volatile resource 2: commit phase start
19:17:29,047 INFO  ResourceManagerFixture:160 - Volatile resource 2: commit phase, calling done
19:17:29,050 INFO  ResourceManagerFixture:163 - Volatile resource 2: commit phase end
19:17:29,050 INFO  ResourceManagerFixture:188 - Single phase Volatile resource 1: transaction completed start
19:17:29,054 INFO  ResourceManagerFixture:190 - Single phase Volatile resource 1: transaction completed middle
19:17:29,057 INFO  ResourceManagerFixture:192 - Single phase Volatile resource 1: transaction completed end
19:17:29,057 INFO  ResourceManagerFixture:188 - Volatile resource 2: transaction completed start
19:17:29,060 INFO  ResourceManagerFixture:190 - Volatile resource 2: transaction completed middle
19:17:29,063 INFO  ResourceManagerFixture:192 - Volatile resource 2: transaction completed end
19:17:29,066 INFO  ResourceManagerFixture:153 - Volatile resource 2: prepare phase end
19:17:29,066 INFO  ResourceManagerFixture:79 - Scope disposed

In presence of only volatile resources, even if one supports single phase commit, the system prepare them all, then perform the volatile second phase for all. So the volatile resource supporting single phase commit has worked with its two phase protocole.

The issue

This causes Npgsql to always prepare transactions when used with code enlisting their own volatile resource, although such case does not need transactions to be prepared server side. As you have likely already guessed, NHibernate does enlist its own volatile resource. So any NHibernate user wanting to use Npgsql and transaction scopes will have to enable prepared transaction on PostgreSQL, even if his transactions are never distributed.

This appears to be a concrete difference between durable and volatile resources. A bit unfortunate it seems not documented, but at least the above test case demonstrates it.

Further technical details

Npgsql version: 3.2.4.1
Operating system: Windows10

@cookav

This comment has been minimized.

Show comment
Hide comment
@cookav

cookav Jul 3, 2017

I think this is similar to #1592. The main difference is that I used EnlistVolatile with EnlistmentOptions.EnlistDuringPrepareRequired to simulate NHibernate session and it worked correctly on Windows but not on Mono.

cookav commented Jul 3, 2017

I think this is similar to #1592. The main difference is that I used EnlistVolatile with EnlistmentOptions.EnlistDuringPrepareRequired to simulate NHibernate session and it worked correctly on Windows but not on Mono.

@fredericDelaporte

This comment has been minimized.

Show comment
Hide comment
@fredericDelaporte

fredericDelaporte Jul 3, 2017

Contributor

Your are right, that is the same. But going back to IPromotableSinglePhaseNotification is likely not adequate. This interface is for delegating the transaction responsibility to an external process, such as a local windows service or even a remote service on the database server.

I am going to comment about that on your issue.

Contributor

fredericDelaporte commented Jul 3, 2017

Your are right, that is the same. But going back to IPromotableSinglePhaseNotification is likely not adequate. This interface is for delegating the transaction responsibility to an external process, such as a local windows service or even a remote service on the database server.

I am going to comment about that on your issue.

@fredericDelaporte

This comment has been minimized.

Show comment
Hide comment
@fredericDelaporte

fredericDelaporte Jul 3, 2017

Contributor

In fact that is not really the same, because mono implementation is not the same of .Net Framework implementation, obviously.

So a working solution for .Net Framework may not work for Mono.

Contributor

fredericDelaporte commented Jul 3, 2017

In fact that is not really the same, because mono implementation is not the same of .Net Framework implementation, obviously.

So a working solution for .Net Framework may not work for Mono.

@roji

This comment has been minimized.

Show comment
Hide comment
@roji

roji Jun 9, 2018

Member

Sorry for disappearing on this. How exactly is this issue different from #1592? If I understand everything correctly, this will all go away if and when Npgsql implements a durable resource manager (#1378)?

@fredericDelaporte, at least from your comment it would seem that the mono issue occurs because it's ignoring EnlistDuringPrepareRequired, and so that would be for them to fix, no?

We may want to also take a look at the latest state of things (e.g. test with a new mono).

Member

roji commented Jun 9, 2018

Sorry for disappearing on this. How exactly is this issue different from #1592? If I understand everything correctly, this will all go away if and when Npgsql implements a durable resource manager (#1378)?

@fredericDelaporte, at least from your comment it would seem that the mono issue occurs because it's ignoring EnlistDuringPrepareRequired, and so that would be for them to fix, no?

We may want to also take a look at the latest state of things (e.g. test with a new mono).

@fredericDelaporte

This comment has been minimized.

Show comment
Hide comment
@fredericDelaporte

fredericDelaporte Jun 9, 2018

Contributor

Well, the main point is to take note #1592 is not a Mono-only thing and should be checked and fixed for the .Net Framework, which may require a different handling than Mono.

@fredericDelaporte, at least from your comment it would seem that the mono issue occurs because it's ignoring EnlistDuringPrepareRequired, and so that would be for them to fix, no?

The issue was appearing only on Mono with NHibernate and Npgsql at that time due to this discrepancy. But now NHIbernate implementation has changed, enlisting things a bit differently in a number of cases, and the overall setup will trigger the issue even without the Mono discrepancy (I mean, on .Net Framework), and will trigger the issue on Mono side too.

The root of the trouble is Npgsql declaring itself as volatile while it has nothing volatile (it is not a memory cache, it is a dataprovider to a database backed in files). MSDTC knows to single phase a transaction when there is one durable resource whatever the number of volatile resources. But if they are all declared as volatile, MSDTC will not guess which one needs to be single phased as much as possible.

Contributor

fredericDelaporte commented Jun 9, 2018

Well, the main point is to take note #1592 is not a Mono-only thing and should be checked and fixed for the .Net Framework, which may require a different handling than Mono.

@fredericDelaporte, at least from your comment it would seem that the mono issue occurs because it's ignoring EnlistDuringPrepareRequired, and so that would be for them to fix, no?

The issue was appearing only on Mono with NHibernate and Npgsql at that time due to this discrepancy. But now NHIbernate implementation has changed, enlisting things a bit differently in a number of cases, and the overall setup will trigger the issue even without the Mono discrepancy (I mean, on .Net Framework), and will trigger the issue on Mono side too.

The root of the trouble is Npgsql declaring itself as volatile while it has nothing volatile (it is not a memory cache, it is a dataprovider to a database backed in files). MSDTC knows to single phase a transaction when there is one durable resource whatever the number of volatile resources. But if they are all declared as volatile, MSDTC will not guess which one needs to be single phased as much as possible.

@roji

This comment has been minimized.

Show comment
Hide comment
@roji

roji Jun 9, 2018

Member

@fredericDelaporte thanks for the added details, and also for the explanation on why enlisting on volatile could trigger this issue - I wasn't aware of that.

I still think the goal should be for proper durable enlisting in 4.1, and I intend to work on it.

Member

roji commented Jun 9, 2018

@fredericDelaporte thanks for the added details, and also for the explanation on why enlisting on volatile could trigger this issue - I wasn't aware of that.

I still think the goal should be for proper durable enlisting in 4.1, and I intend to work on it.

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