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 1lgcGO-000344-9w for pgsql-odbc@arkaria.postgresql.org; Tue, 11 May 2021 23:58:08 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1lgcGK-00040x-He for pgsql-odbc@arkaria.postgresql.org; Tue, 11 May 2021 23:58:04 +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 1lgcGK-00040o-8k for pgsql-odbc@lists.postgresql.org; Tue, 11 May 2021 23:58:04 +0000 Received: from mail-ej1-x630.google.com ([2a00:1450:4864:20::630]) by magus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.92) (envelope-from ) id 1lgcGC-00024r-Uo for pgsql-odbc@postgresql.org; Tue, 11 May 2021 23:58:03 +0000 Received: by mail-ej1-x630.google.com with SMTP id k10so1086562ejj.8 for ; Tue, 11 May 2021 16:57:56 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=mime-version:references:in-reply-to:from:date:message-id:subject:to :cc; bh=5L4rsMiqDgdZGWVPjaxwaSvDTe7fLrqq9QZK54WqCTE=; b=K1wo6iVDaJS41u9kTunxk08JXMLktjvk17rDTe/bTphPN3fnqM7y8Th9B33SD5tPzI NSWLyHEUDdrlacMVeGrYXTrndGO13W+0SD+insL5o/nHV6+x73GOZM0loiX24AGUqsUB gzphux18+x3SUS8+SwbKqYyG0xrVcfZHawlUC7mttUrvr3juEIJbrte4nP3i22LcOjQB 2ALm0DbD3Q/eqe+W/2WCDdowW2b9qf3eqa5bOhHwhn/pjvn5BSeDs384zoxYQNe7emMv j1T8rBrbj/2mysTZhAIJStl4TO3v1TTyh5Bl1fbi54tKLersxo00QowuFX2vUX8aSJqT M0Rw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:references:in-reply-to:from:date :message-id:subject:to:cc; bh=5L4rsMiqDgdZGWVPjaxwaSvDTe7fLrqq9QZK54WqCTE=; b=ZCmvHTowTGUyJN+VDmV6a8aIwuwP7ES2MtH70NnMJEZV9D2n1NlJFQYnWtaQo4968P PzUy3YRwrR9Nnxs3nz1Ab//mKygYwNtLrfpY6xBt10Sa8vFeb5W1sumaWtYYesgSvGjp GWrUaXYGDV6TydtB/wicfM0X8u5+DcRGWth52zkpGTLMST9AUrw5fMEw6xICJHUhOXRO hjwpDiH5vJTKDi+kBv2S4v3ozsQZJJKIpbQjALtjphvp/bwt4OUhWCB6qO0if3TTw+bP PvpQrxXJuWTivGi9g5ldTDVI+fNlM75vE5zsQ7x7wBPW38ma/VjMzLFBgij+ob9UmCcI 7uOQ== X-Gm-Message-State: AOAM530h8+IhiQak5bmTUaEe4kTrVghhBPHhDwLWh93lNEKWIMtmrur7 xdxVpOtJUxPIEYMMKnsQjsUT1p1hDwrPVbzIrIU= X-Google-Smtp-Source: ABdhPJywmD7ecFgBB9c3npq5wafMXxhtFS1a6OK/Pisew8hYUeJtmF7htvb5W2YNlmAX0iy+K5QwxYWSe3Ro/e5Tv18= X-Received: by 2002:a17:907:d25:: with SMTP id gn37mr32990121ejc.538.1620777475147; Tue, 11 May 2021 16:57:55 -0700 (PDT) MIME-Version: 1.0 References: In-Reply-To: From: "Inoue,Hiroshi" Date: Wed, 12 May 2021 08:57:43 +0900 Message-ID: Subject: Re: PostgreSQL ODBC mylog() uses lots of CPU in INTEGER field SQL query To: Marko Ristola Cc: "pgsql-odbc@postgresql.org" Content-Type: multipart/alternative; boundary="000000000000aa8acb05c216a934" List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk --000000000000aa8acb05c216a934 Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable Hi Marko, I would take care of your patch. Thanks. Hiroshi Inoue 2021=E5=B9=B45=E6=9C=888=E6=97=A5(=E5=9C=9F) 4:31 Marko Ristola : > I did a query of 4 million rows into an INTEGER field. > > Linux perf shows following profile (hottest functions): > > 9.91% bc_sqlselect psqlodbcw.so [.] mylog > 9.64% bc_sqlselect psqlodbcw.so [.] > QR_read_a_tuple_from_db > 4.83% bc_sqlselect psqlodbcw.so [.] > copy_and_convert_field > 4.57% bc_sqlselect libpthread-2.17.so [.] > pthread_mutex_unlock > 4.51% bc_sqlselect libpthread-2.17.so [.] pthread_mutex_lock > 4.40% bc_sqlselect psqlodbcw.so [.] > SOCK_get_next_n_bytes.part.2 > 3.93% bc_sqlselect psqlodbcw.so [.] PGAPI_ExtendedFetc= h > > Following patch removes the only mylog() call (not a macro) > > from the PostgreSQL ODBC driver from consuming CPU: > > (MYLOG() macro is used to avoid the heavy mylog() call.) > > > diff --git a/results.c b/results.c > index 1f6a12c..ec89600 100644 > --- a/results.c > +++ b/results.c > @@ -4632,7 +4632,6 @@ SC_pos_add(StatementClass *stmt, > goto cleanup; > } > MYLOG(0, "addstr=3D%s\n", addstr.data); > - mylog("addstr=3D%s\n", addstr.data); > s.qstmt->exec_start_row =3D s.qstmt->exec_end_row =3D s.i= row; > s.updyes =3D TRUE; > ret =3D PGAPI_ExecDirect(hstmt, (SQLCHAR *) addstr.data, > SQL_NTS, 0); > > > Best Regards, Marko Ristola > > -- > Marko Ristola > Software developer > BC Platforms > > m. +358 40 593 2182 > e. marko.ristola@bcplatforms.com > w. www.bcplatforms.com > --000000000000aa8acb05c216a934 Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable
Hi Marko,

I would take care of your pat= ch.

Thanks.
Hiroshi Inoue
2021=E5= =B9=B45=E6=9C=888=E6=97=A5(=E5=9C=9F) 4:31 Marko Ristola <marko.ristola@bcplatforms.com>:
=

I did a query of 4 million rows into an INTEGER field.

Linux perf shows following profile (hottest functions):

=C2=A0=C2=A0 9.91%=C2=A0 bc_sqlselect=C2=A0 psqlodbcw.so=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 [.] m= ylog=C2=A0
=C2=A0=C2=A0 9.64%=C2=A0 bc_sqlselect=C2=A0 psqlodbcw.so=C2=A0=C2=A0=C2=A0= =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 [.] QR_r= ead_a_tuple_from_db
=C2=A0=C2=A0 4.83%=C2=A0 bc_sqlselect=C2=A0 psqlodbcw.so=C2=A0=C2=A0=C2=A0= =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 [.] copy= _and_convert_field
=C2=A0=C2=A0 4.57%=C2=A0 bc_sqlselect=C2=A0 libpthread-2.17.so=C2=A0=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0=C2=A0 [.] pthread_mutex_unlock
=C2=A0=C2=A0 4.51%=C2=A0 bc_sqlselect=C2=A0 libpthread-2.17.so=C2=A0=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0=C2=A0 [.] pthread_mutex_lock
=C2=A0=C2=A0 4.40%=C2=A0 bc_sqlselect=C2=A0 psqlodbcw.so=C2=A0=C2=A0=C2=A0= =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 [.] SOCK= _get_next_n_bytes.part.2
=C2=A0=C2=A0 3.93%=C2=A0 bc_sqlselect=C2=A0 psqlodbcw.so=C2=A0=C2=A0=C2=A0= =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 [.] PGAP= I_ExtendedFetch

Following patch removes the only mylog() call (not a macro)

from t= he PostgreSQL ODBC driver from consuming CPU:

(MYLOG() macro is used to avoid the heavy mylog() call.)


diff --git a/results.c b/results.c
index 1f6a12c..ec89600 100644
--- a/results.c
+++ b/results.c
@@ -4632,7 +4632,6 @@ SC_pos_add(StatementClass *stmt,
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 goto cleanu= p;
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0 }
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0 MYLOG(0, "addstr=3D%s\n", addstr.data);
-=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0= =C2=A0=C2=A0 mylog("addstr=3D%s\n", addstr.data);
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0 s.qstmt->exec_start_row =3D s.qstmt->exec_end_row =3D= s.irow;
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0 s.updyes =3D TRUE;
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0 ret =3D PGAPI_ExecDirect(hstmt, (SQLCHAR *) addstr.data, SQ= L_NTS, 0);


Best Regards, Marko Ristola

--

Marko Ristola
Software developer
= BC Platforms

m. +358 40 593 2182
e. marko.ristola@bcplatforms.com
= w. www.bcplatforms= .com
--000000000000aa8acb05c216a934--