Skip to content
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

connection is already in state 'Executing' when inserting lots of objects [Using Dapper] #1776

Closed
thedumbtechguy opened this issue Jan 13, 2018 · 18 comments

Comments

@thedumbtechguy
Copy link

thedumbtechguy commented Jan 13, 2018

I submitted a report on the dapper repo for this issue as well. DapperLib/Dapper#919

Steps to reproduce

Essentially, I have a bit of code that inserts rows into 2 tables. The second table has a Foreign Key to the first.

using (TransactionScope scope = new TransactionScope(TransactionScopeOption.Required, TransactionScopeAsyncFlowOption.Enabled))
{	
	const string query = @"WITH updated as (
					INSERT INTO public.schedule_row
					(id, schedule_id, petraid, ssnit, staffid, fullname, salary, total, created_by, validation_messages)
					VALUES
					(@Id, @ScheduleId, @PetraId, @Ssnit, @StaffId, @Fullname, @Salary, @Total, @ModifiedBy, @ValidationMessage)
				)
				UPDATE public.schedule
				SET
					is_valid = false
					,   updated_by = @ModifiedBy
					,   updated_at = now()
					,   validation_processed_at = NULL
					,   validation_reminders_count = 0
					,   validation_reminder_last_sent_at = NULL
				WHERE id = @ScheduleId;
			";

	var rows_ = rows.Select(sc =>
	{
		var total = sc.Contributions.Sum(c => string.IsNullOrWhiteSpace(c.Amount) ? 0 : Decimal.Parse(c.Amount));
		var salary = string.IsNullOrWhiteSpace(sc.Salary) ? 0 : Decimal.Parse(sc.Salary);

		var petraId = sc.PetraId?.ToUpper();
		petraId = petraId?.StartsWith("H1") ?? false ? petraId.Replace("H1", "HI") : petraId;
		return new
		{
			Id = NewId.NextGuid(),
			ScheduleId = scheduleId,
			PetraId = petraId,
			Ssnit = sc.Ssnit,
			StaffId = sc.StaffId,
			Fullname = sc.Fullname,
			Salary = salary,
			Total = total,
			ModifiedBy = modifiedBy,
			Contributions = sc.Contributions,
			ValidationMessage = new String[] { "Not validated yet" }
		};
	}).ToArray();

	var count = await conn.ExecuteAsync(query, rows_).ConfigureAwait(false);

	if (count > 0)
	{
		const string contributionsQuery = @"
				INSERT INTO public.schedule_row_contribution
				(schedule_row_id, deal_contribution_type, amount)
				VALUES
				(@ScheduleRowId, @DealContributionType, @Amount)
				ON CONFLICT (schedule_row_id, deal_contribution_type)
				DO NOTHING
			";

		var _rowContributions = rows_.SelectMany(r => r.Contributions.Select(c => new
		{
			ScheduleRowId = r.Id,
			DealContributionType = c.DealContributionType,
			Amount = string.IsNullOrWhiteSpace(c.Amount) ? 0 : Decimal.Parse(c.Amount),
		})).ToArray();
		await conn.ExecuteAsync(contributionsQuery, _rowContributions).ConfigureAwait(false);
	}
}

The issue

The code works find and we haven't had any issues.

I noticed however that an exception is thrown when the number of rows being inserted into both tables is more than approximately 20k total. In my case, I had about 11244 items in each list.

I made sure all calls are awaited so I do not get promoted to a distributed transaction since this is net core 2.0.

I run tests where I split the rows into batches of 5000 in an attempt to test. The exception gets thrown at around the 3rd or 4th iteration.

I am totally stumped here. Any pointers?

Exception message: The connection is already in state 'Executing'
Stack trace:

Npgsql.NpgsqlOperationInProgressException: The connection is already in state 'Executing'
   at Npgsql.NpgsqlConnector.StartUserAction(ConnectorState newState, NpgsqlCommand command)
   at Npgsql.NpgsqlCommand.<ExecuteNonQuery>d__84.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Npgsql.NpgsqlCommand.<>c__DisplayClass83_0.<<ExecuteNonQueryAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Dapper.SqlMapper.<ExecuteMultiImplAsync>d__36.MoveNext() in C:\projects\dapper\Dapper\SqlMapper.Async.cs:line 622
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()

Further technical details

Npgsql version: 3.2.6
PostgreSQL version: 9.6
Operating system: Windows 10

Other details about my project setup:
Net Core 2.0

@thedumbtechguy
Copy link
Author

So after some more debugging.

I noticed the CommandInProgress property of the exception is null. Not sure if that means anything.

image

I also turned on logging for npgsql and have this.

It starts with

Petra.TransferAgency.Web> Beginning transaction with isolation level Serializable
Petra.TransferAgency.Web> Enlisted volatile resource manager (localid=8944801f-051c-43fd-b201-44b6fcc48231:1)
Petra.TransferAgency.Web> Executing statement(s):
Petra.TransferAgency.Web> 	INSERT INTO public.schedule
Petra.TransferAgency.Web>                             (share_class_id, client_petraid, created_by, updated_by)
Petra.TransferAgency.Web>                             VALUES
Petra.TransferAgency.Web>                             ($1, $2, $3, $3)
Petra.TransferAgency.Web>                             RETURNING *
Petra.TransferAgency.Web>                         
Petra.TransferAgency.Web> Parameters:
Petra.TransferAgency.Web> 	$1: 1	$2: CO00000011	$3: 1

and ends with an abrupt rollback

Petra.TransferAgency.Web> Executing statement(s):
Petra.TransferAgency.Web> 	
Petra.TransferAgency.Web>                             INSERT INTO public.schedule_row_contribution
Petra.TransferAgency.Web>                             (schedule_row_id, deal_contribution_type, amount)
Petra.TransferAgency.Web>                             VALUES
Petra.TransferAgency.Web>                             ($1, $2, $3)
Petra.TransferAgency.Web>                             ON CONFLICT (schedule_row_id, deal_contribution_type)
Petra.TransferAgency.Web>                             DO NOTHING
Petra.TransferAgency.Web>                         
Petra.TransferAgency.Web> Parameters:
Petra.TransferAgency.Web> 	$1: 5e460000-6ade-4ccc-9f56-08d55a9b6a81	$2: contribution	$3: 5
Petra.TransferAgency.Web> Executing statement(s):
Petra.TransferAgency.Web> 	
Petra.TransferAgency.Web>                             INSERT INTO public.schedule_row_contribution
Petra.TransferAgency.Web>                             (schedule_row_id, deal_contribution_type, amount)
Petra.TransferAgency.Web>                             VALUES
Petra.TransferAgency.Web>                             ($1, $2, $3)
Petra.TransferAgency.Web>                             ON CONFLICT (schedule_row_id, deal_contribution_type)
Petra.TransferAgency.Web>                             DO NOTHING
Petra.TransferAgency.Web>                         
Petra.TransferAgency.Web> Parameters:
Petra.TransferAgency.Web> 	$1: 5e460000-6ade-4ccc-9f61-08d55a9b6a81	$2: contribution	$3: 5
Petra.TransferAgency.Web> Rolling back transaction

@thedumbtechguy
Copy link
Author

For anyone wondering, I switched to using postgresql_bulk_insert for the larger inserts.
It works very very fast.

@roji
Copy link
Member

roji commented Mar 8, 2018

Sorry for taking so long to answer with this.

It seems that postgresql_bulk_insert is a simple wrapper for the Npgsql COPY API, which you can also call directly.

But I'm interested in understanding the original problem. Is there any way you can submit a small repro with Dapper that triggers the exception? That would allow me to investigate.

@roji roji added the invalid label Mar 8, 2018
@roji
Copy link
Member

roji commented Jun 9, 2018

Closing as no further information has been provided.

@roji roji closed this as completed Jun 9, 2018
@YVishnevsky
Copy link

YVishnevsky commented May 25, 2020

I have faced the same issue.
table:

CREATE TABLE public.test_table1
(
    id integer NOT NULL GENERATED BY DEFAULT AS IDENTITY ( INCREMENT 1 START 1 MINVALUE 1 MAXVALUE 2147483647 CACHE 1 ),
    name citext COLLATE pg_catalog."default",
    CONSTRAINT test_table1_pkey PRIMARY KEY (id)
)

Sample program:

using Dapper;
using System;
using System.Transactions;

namespace ConsoleAppPostgre
{
    class Program
    {
        static void Main(string[] args)
        {
            using var scope = new TransactionScope(TransactionScopeOption.Required, TimeSpan.FromSeconds(0));
            using var cn = new Npgsql.NpgsqlConnection("Host=10.67.1.238;Database=erc_households_test5;Username=zhoec_app;Password=2020");
            using var cm = cn.CreateCommand();
            cn.Open();
            Console.Write($"Processed records: ");
            var cursorTop = Console.CursorTop;
            for (int i = 0; i<1_000_000; i++ )
            {
                cn.Execute(@"INSERT INTO test_table1(name) VALUES (@name);", new { name = Guid.NewGuid().ToString() });
                Console.Write(i);
                Console.SetCursorPosition(19, cursorTop);
            }

            scope.Complete();
            Console.WriteLine("\nAll done.");
        }
    }
}

I get Npgsql.NpgsqlOperationInProgressException: 'The connection is already in state 'Executing'' after inserting ~400k records. In real project schema is more complex and exception occures after inserting ~100k records

.net core 3.1
Npgsql 4.1.3.1
Dapper 2.0.35

@YohDeadfall YohDeadfall self-assigned this May 25, 2020
@YohDeadfall YohDeadfall reopened this May 25, 2020
@roji roji added this to the 4.1.4 milestone May 25, 2020
@YohDeadfall
Copy link
Contributor

Was not able to replicate the issue. Could you provide the full stack trace?

@YVishnevsky
Copy link

YVishnevsky commented May 25, 2020

" at Npgsql.NpgsqlConnector.<StartUserAction>g__DoStartUserAction|187_0(<>c__DisplayClass187_0& )\r\n at Npgsql.NpgsqlConnector.StartUserAction(ConnectorState newState, NpgsqlCommand command)\r\n at Npgsql.NpgsqlCommand.<ExecuteReaderAsync>d__102.MoveNext()\r\n at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()\r\n at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)\r\n at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)\r\n at Npgsql.NpgsqlCommand.<ExecuteNonQuery>d__92.MoveNext()\r\n at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()\r\n at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)\r\n at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)\r\n at Npgsql.NpgsqlCommand.ExecuteNonQuery()\r\n at Dapper.SqlMapper.ExecuteCommand(IDbConnection cnn, CommandDefinition& command, Action``2 paramReader) in /_/Dapper/SqlMapper.cs:line 2797\r\n at Dapper.SqlMapper.ExecuteImpl(IDbConnection cnn, CommandDefinition& command) in /_/Dapper/SqlMapper.cs:line 568\r\n at Dapper.SqlMapper.Execute(IDbConnection cnn, String sql, Object param, IDbTransaction transaction, Nullable1 commandTimeout, Nullable1 commandType) in /_/Dapper/SqlMapper.cs:line 441\r\n at ConsoleAppPostgre.Program.Main(String[] args) in D:\\Projects\\ConsoleApp3\\Program.cs:line 19

image

@YohDeadfall
Copy link
Contributor

Okay, could you enable logs in Npgsql and paste them here? There should be a started action which has no corresponding end message:

Log.Trace("Start user action", Id);

Log.Trace("End user action", Id);

If you can patch the driver a bit first and output newState in DoStartUserAction, it would be awesome.

@YVishnevsky
Copy link

I've got another exception after turning on logging with trace level.
At some point I saw messages
---trace
....
Single-phase transaction rollback (localid=6f4e39df-6b9d-494d-9e79-23d4ad6f1fe7:1)
Rolling back transaction
Cleaning up reader
End user action
Start user action
Executing statement(s):
INSERT INTO test_table1(name) VALUES ($1)

Connection in use while trying to rollback, will cancel and retry (localid=6f4e39df-6b9d-494d-9e79-23d4ad6f1fe7:1
Sending cancellation...
Attempting to connect to 10.67.1.238:5432
Cleaning up reader
End user action
...
..
Rolling back transaction
Connection in use while trying to rollback, will cancel and retry (localid=6f4e39df-6b9d-494d-9e79-23d4ad6f1fe7:1
Sending cancellation...
Attempting to connect to 10.67.1.238:5432
Cleaning up reader
End user action
Start user action
Executing statement(s):
INSERT INTO test_table1(name) VALUES ($1)

Socket connected to 10.67.1.238:5432
Cleaning up connector
Cleaning up reader
End user action
Start user action
Executing statement(s):
INSERT INTO test_table1(name) VALUES ($1)

Cleaning up reader
End user action
...
...
Start user action
Executing statement(s):
INSERT INTO test_table1(name) VALUES ($1)

Exception during transaction rollback (localid=6f4e39df-6b9d-494d-9e79-23d4ad6f1fe7:1)
System.Exception: Could not roll back after 20 attempts, aborting. Transaction is in an unknown state.
at Npgsql.VolatileResourceManager.RollbackLocal()
at Npgsql.VolatileResourceManager.Rollback(Enlistment enlistment)
Cleaning up resource manager (localid=6f4e39df-6b9d-494d-9e79-23d4ad6f1fe7:1
End user action

In VS:
image

@rudi-bruchez
Copy link

Hello, I've got the same problem. When using Nuget version I've got a Dictionary index out of bound kind of message from Npgsql. Forked and integrated the last version of Npgsql in my project, and now seeing this message when inserting in a loop. Will try to get more information for you about this.

@YohDeadfall
Copy link
Contributor

@rudi-bruchez Do you have the problem in case if parallel execution or not? If you're able to reproduce the problem with using one thread or at least their count is less than PostgreSQL allows (see the settings), then I can take another look and fix it. With the example posted by @YVishnevsky am not able to reproduce it anymore (got it a few times only and detected some area, but it's still very large to understand the root).

@rudi-bruchez
Copy link

rudi-bruchez commented Jun 14, 2020

I'm pretty sure I can reproduce it. I'm in a synchronous call but in a transaction (TransactionScope), looping individual inserts, it is my first test, I want to batch inserts afterwards or using COPY. But when I'm throwing individual inserts at PG, after about 400 inserts I get the problem. If I'm running 100 I'm OK. Will try to get you specific info.

@YohDeadfall
Copy link
Contributor

Well, post the code and I will investigate. It would be better to avoid dapper if possible.

@rudi-bruchez
Copy link

rudi-bruchez commented Jun 14, 2020

I'm not using Dapper, plain npgsql calls. Sorry to mix subjects here, but I'm confused about thransactions : I'm using TransactionScope betwen SQL Server DELETE and PG INSERT, and it seems the transaction is getting rolled back. Does it try to create a distributed transaction and should I use enlist=false and manage the PG transaction manually?

My code for now is very straightforward:

try
            {
                using var conn = new NpgsqlConnection(connString);
                conn.Open();
                using var cmd = new NpgsqlCommand
                {
                    Connection = conn
                };
                var i = 1;
                foreach (var insert in inserts)
                {
                    cmd.CommandText = insert;
                    cmd.ExecuteNonQuery(); // TODO Async
                    Log.Information($"row {i} inserted");
                    i++;
                }
            }
            catch (Exception e)
            {
                Log.Error(e.Message);
                throw;
            }

inserts is a List with insert statements in it. Nothing else, except it is enlisted in the TransactionScope

@YohDeadfall
Copy link
Contributor

What is the query and schema?

@rudi-bruchez
Copy link

Let me anonymize it, I'll send you some code to repro

@roji roji modified the milestones: 4.1.4, 4.1.5 Jul 19, 2020
@YohDeadfall
Copy link
Contributor

@rudi-bruchez, any chance to post the repro?

@YohDeadfall YohDeadfall removed the bug label Sep 28, 2020
@YohDeadfall YohDeadfall removed this from the 4.1.5 milestone Sep 28, 2020
@YohDeadfall YohDeadfall removed their assignment Sep 28, 2020
@YohDeadfall
Copy link
Contributor

Closing since no repro was posted back.

@roji roji closed this as completed Jan 17, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants