Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1okOFO-0001OO-Ut for psycopg@arkaria.postgresql.org; Mon, 17 Oct 2022 11:25:31 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1okOFM-00053g-3z for psycopg@arkaria.postgresql.org; Mon, 17 Oct 2022 11:25:28 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1okOFL-00053X-Pg for psycopg@lists.postgresql.org; Mon, 17 Oct 2022 11:25:27 +0000 Received: from mail-yb1-xb2a.google.com ([2607:f8b0:4864:20::b2a]) by magus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.92) (envelope-from ) id 1okOFJ-0008DP-Po for psycopg@postgresql.org; Mon, 17 Oct 2022 11:25:27 +0000 Received: by mail-yb1-xb2a.google.com with SMTP id r3so12870176yba.5 for ; Mon, 17 Oct 2022 04:25:25 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20210112; h=to:subject:message-id:date:from:mime-version:from:to:cc:subject :date:message-id:reply-to; bh=K858c5ucRchzUQdVxv683nhx/JcxTH7+G6f1bK5wMR8=; b=DG5UywBfJw/vuKWVIBlgfV8rCA610FMYk0c1BSUTsB2dBSIp9ef2gVhjn4O29fTipx xTR1b5IZXzgjWGdKTHTFnfUWIcxM4AeNKsj8Tjq4v4pMo2vlaKIu6Q0+ywWungPw5xIs TdUQKiqR7sr6lxjBFJ9cWFWSJRV2ZPpFHAIFeZV6lnd/U3mqFG2Ekt/RMCw4wUbteH29 AbxZsZFpJv1UDcBnxbdN6vxk25Z2L9eBPM5uXPplorjnWw+PYfg6gIJy+xggSScsrJBp QI0jILEtIQZbrHtem5eDCZBSAsYo0PAbLeaVQ8Sv4kQg7E5AGDR7/2ZhsW/P01tcMn9u 8f0w== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=to:subject:message-id:date:from:mime-version:x-gm-message-state :from:to:cc:subject:date:message-id:reply-to; bh=K858c5ucRchzUQdVxv683nhx/JcxTH7+G6f1bK5wMR8=; b=vdEu984yJtkjZ3tyBprNHautx4R/QoZLsAi1Gwso4rfTfQbyvGRUVTzRELJYzrMILU SfvxJV1gAKC4pKg2WWfJIZTgYfkjXHrALVLCqwtZ2FeviF7+w1dr7mCL3yUkBa4jKodS ZEe3ms/BUDJCIVOeesAGxkkUC3WMYVC908pr9MyKYV47rQLyaY5m4cJdXFGrlWhgV1tt 0BMeMfrmqRUWHlL5dL5HYvmr7txWNnGjyEy4HV+Xtd+d8bDWhD+ezMJ7bfDluJD9a8ML Cna1ZaxzbPrzGNcgJ9RUUb0+tpnBiwgGmJgxdnHhKrIrU/e10t33gGYRSdEDnaQ8963l ptxw== X-Gm-Message-State: ACrzQf3n4vaen5V24XTG+Q5vP2ItT2Qc+Z9Lhe7Xfr3ziOKgt7gXEnYc eC/INcoGcas5GevFhys+9Hu9qws1uIglquSLBfGAGQVEO5g= X-Google-Smtp-Source: AMsMyM5dfJsVVU2iPJ+d3Ux+hq4DrmAUZyfaUHtcxdgGmFO3cPzs86VUEmWvtcsRxzVDIYj00EZhiRHPnmqkF9UB/A8= X-Received: by 2002:a25:509:0:b0:6be:aabc:e80c with SMTP id 9-20020a250509000000b006beaabce80cmr9056581ybf.390.1666005923953; Mon, 17 Oct 2022 04:25:23 -0700 (PDT) MIME-Version: 1.0 From: Stefan Knecht Date: Mon, 17 Oct 2022 18:25:14 +0700 Message-ID: Subject: Puzzling situation with threads and psycopg2 on RDS To: psycopg@postgresql.org Content-Type: multipart/alternative; boundary="0000000000004a804105eb393bdd" List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk --0000000000004a804105eb393bdd Content-Type: text/plain; charset="UTF-8" Hello I have this situation now, that I can't wrap my head around and I'm hoping someone can shed some light onto what is going on, before I spend hours trying to reproduce this by taking the code apart into a test case. A few facts: - I've got a piece of code split into several classes. - It initializes a dynamic number of threads. For the sake of this topic, I'll stick to just 2 threads to illustrate. - Each thread creates its own database connection (psycopg2.connect()) when it's started - Each thread, for each task it does, prints out its own name and the PID of the database session. Running the code, I see this: Threadcount 2 Starting thread Thread-1 Starting thread Thread-2 Thread-1 CONNECT Thread-2 CONNECT Thread-2 Run plan <<'Create basic order'>> Thread-2 Processing query block <'Query block 1'> Thread-2 File 'select_random_product.sql' Thread-1 Run plan <<'Create basic order'>> Thread-1 Processing query block <'Query block 1'> Thread-1 File 'select_random_product.sql' Thread-2 PID 31909 Thread-2 PID 31908 Thread-2 File 'select_random_customer.sql' Thread-2 PID 31908 Thread-2 File 'create_simple_order.sql' Thread-1 File 'select_random_customer.sql' Thread-2 PID 31908 Thread-2 File 'modify_simple_order.sql' Thread-2 PID 31908 Thread-1 File 'create_simple_order.sql' Thread-2 PID 31908 Thread-2 PID 31908 Thread-1 File 'modify_simple_order.sql' Thread-2 PID 31908 All threads exited. In the database log, with full logging enabled, I see this: 2022-10-17 10:59:03 UTC:10.0.1.17(36350):[unknown]@[unknown]:[31908]:LOG: connection received: host=10.0.1.17 port=36350 2022-10-17 10:59:03 UTC:10.0.1.17(36356):[unknown]@[unknown]:[31909]:LOG: connection received: host=10.0.1.17 port=36356 2022-10-17 10:59:03 UTC:10.0.1.17(36356):postgres@postgres:[31909]:LOG: connection authorized: user=postgres database=postgres SSL enabled (protocol=TLSv1.2, cipher=ECDHE-RSA-AES256-GCM-SHA384, bits=256, compression=off) 2022-10-17 10:59:03 UTC:10.0.1.17(36350):postgres@postgres:[31908]:LOG: connection authorized: user=postgres database=postgres SSL enabled (protocol=TLSv1.2, cipher=ECDHE-RSA-AES256-GCM-SHA384, bits=256, compression=off) 2022-10-17 10:59:03 UTC:10.0.1.17(36356):postgres@postgres:[31909]:LOG: execute : BEGIN 2022-10-17 10:59:03 UTC:10.0.1.17(36350):postgres@postgres:[31908]:LOG: execute : BEGIN 2022-10-17 10:59:03 UTC:10.0.1.17(36350):postgres@postgres:[31908]:LOG: duration: 0.065 ms 2022-10-17 10:59:03 UTC:10.0.1.17(36356):postgres@postgres:[31909]:LOG: statement: select pg_backend_pid(); 2022-10-17 10:59:03 UTC:10.0.1.17(36356):postgres@postgres:[31909]:LOG: duration: 0.246 ms 2022-10-17 10:59:03 UTC:10.0.1.17(36350):postgres@postgres:[31908]:LOG: statement: select pg_backend_pid(); 2022-10-17 10:59:03 UTC:10.0.1.17(36350):postgres@postgres:[31908]:LOG: duration: 0.237 ms 2022-10-17 10:59:03 UTC:10.0.1.17(36356):postgres@postgres:[31909]:LOG: disconnection: session time: 0:00:00.021 user=postgres database=postgres host=10.0.1.17 port=36356 2022-10-17 10:59:03 UTC:10.0.1.17(36350):postgres@postgres:[31908]:LOG: statement: .... many more entries from 31908 Perhaps you can already see the problem. One thread randomly disconnects. We can see this in several places. 1) In the script's output, we can see that Thread-2 first reports PID 31909 and then switches to 31908. 31909 goes silent. and 2) The database log shows the same thing: - 2 sessions connect - 2 sessions get established - shortly after, one disconnects, and the other keeps connected and executes the entire workload of both threads. In order. If I start with 3 threads, I see basically the same thing. Two will disconnect right after connecting, and the remaining one will then run all 3 tasks. Any ideas why this is happening? Thank you! --0000000000004a804105eb393bdd Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable
Hello

I have this= situation now, that I can't wrap my head around and I'm hoping som= eone can shed some light onto what is going on, before I spend hours trying= to reproduce this by taking the code apart into a test case.

A few facts:

-=20 I've got a piece of code split into several classes.
- I= t initializes a dynamic number of threads. For the sake of this topic, I= 9;ll stick to just 2 threads to illustrate.
- Each thread cre= ates its own database connection (psycopg2.connect()) when it's started=
- Each thread, for each task it does, prints out its own nam= e and the PID of the database session.

Running the= code, I see this:

Threadcount 2
Starting thread Thread-1
Starting thread Thread-= 2
Thread-1 CONNECT
Thread-2 CONNECT
Thread-2 Run plan <<'= ;Create basic order'>>
=C2=A0 Thread-2 Processing query block = <'Query block 1'>
=C2=A0 =C2=A0 Thread-2 File 'select_= random_product.sql'
Thread-1 Run plan <<'Create basic orde= r'>>
=C2=A0 Thread-1 Processing query block <'Query blo= ck 1'>
=C2=A0 =C2=A0 Thread-1 File 'select_random_product.sql= '
=C2=A0 =C2=A0 Thread-2 PID 31909
=C2=A0 =C2=A0 Thread-2 PID 319= 08
=C2=A0 =C2=A0 Thread-2 File 'select_random_customer.sql'
= =C2=A0 =C2=A0 Thread-2 PID 31908
=C2=A0 =C2=A0 Thread-2 File 'create= _simple_order.sql'
=C2=A0 =C2=A0 Thread-1 File 'select_random_cu= stomer.sql'
=C2=A0 =C2=A0 Thread-2 PID 31908
=C2=A0 =C2=A0 Thread= -2 File 'modify_simple_order.sql'
=C2=A0 =C2=A0 Thread-2 PID 319= 08
=C2=A0 =C2=A0 Thread-1 File 'create_simple_order.sql'
=C2= =A0 =C2=A0 Thread-2 PID 31908
=C2=A0 =C2=A0 Thread-2 PID 31908
=C2=A0= =C2=A0 Thread-1 File 'modify_simple_order.sql'
=C2=A0 =C2=A0 Th= read-2 PID 31908
All threads exited.


In the database log, with full logging enabled, = I see this:

= 2022-10-17 10:59:03 UTC:10.0.1.17(36350):[unknown]@[unknown]:[31908]:LOG: = =C2=A0connection received: host=3D10.0.1.17 port=3D36350
2022-10-17 10:5= 9:03 UTC:10.0.1.17(36356):[unknown]@[unknown]:[31909]:LOG: =C2=A0connection= received: host=3D10.0.1.17 port=3D36356
2022-10-17 10:59:03 UTC:10.0.1.= 17(36356):postgres@postgres:[31909]:LOG: =C2=A0connection authorized: user= =3Dpostgres database=3Dpostgres SSL enabled (protocol=3DTLSv1.2, cipher=3DE= CDHE-RSA-AES256-GCM-SHA384, bits=3D256, compression=3Doff)
2022-10-17 10= :59:03 UTC:10.0.1.17(36350):postgres@postgres:[31908]:LOG: =C2=A0connection= authorized: user=3Dpostgres database=3Dpostgres SSL enabled (protocol=3DTL= Sv1.2, cipher=3DECDHE-RSA-AES256-GCM-SHA384, bits=3D256, compression=3Doff)=
2022-10-17 10:59:03 UTC:10.0.1.17(36356):postgres@postgres:[31909]:LOG:= =C2=A0execute <unnamed>: BEGIN
2022-10-17 10:59:03 UTC:10.0.1.17(= 36350):postgres@postgres:[31908]:LOG: =C2=A0execute <unnamed>: BEGIN<= br>2022-10-17 10:59:03 UTC:10.0.1.17(36350):postgres@postgres:[31908]:LOG: = =C2=A0duration: 0.065 ms
2022-10-17 10:59:03 UTC:10.0.1.17(36356):postgr= es@postgres:[31909]:LOG: =C2=A0statement: select pg_backend_pid();
2022-= 10-17 10:59:03 UTC:10.0.1.17(36356):postgres@postgres:[31909]:LOG: =C2=A0du= ration: 0.246 ms
2022-10-17 10:59:03 UTC:10.0.1.17(36350):postgres@postg= res:[31908]:LOG: =C2=A0statement: select pg_backend_pid();
2022-10-17 10= :59:03 UTC:10.0.1.17(36350):postgres@postgres:[31908]:LOG: =C2=A0duration: = 0.237 ms
2022-10-17 10:59:03 UTC:10.0.1.17(36356):postgres@postgres:[319= 09]:LOG: =C2=A0disconnection: session time: 0:00:00.021 user=3Dpostgres dat= abase=3Dpostgres host=3D10.0.1.17 port=3D36356
2022-10-17 10:59:03 UTC:1= 0.0.1.17(36350):postgres@postgres:[31908]:LOG: =C2=A0statement: .... many m= ore entries from 31908


Perhaps you can already see the problem. One thread randomly disco= nnects.
=
We can see this in = several places.

1) In the script= 's output, we can see that Thread-2 first reports PID 31909 and then sw= itches to 31908.=20 31909 goes silent.

and 2) Th= e database log shows the same thing:

<= /div>
- 2 sessions connect
- 2 sessions get established
- shortly after, one disconnects, and the other keeps con= nected and executes the entire workload of both threads. In order.

If I start with 3 threads, I see basical= ly the same thing. Two will disconnect right after connecting, and the rema= ining one will then run all 3 tasks.

Any ideas why this is happening?


Thank you!

=













--0000000000004a804105eb393bdd--