Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.84_2) (envelope-from ) id 1dpC2L-000366-JK for pgsql-performance@arkaria.postgresql.org; Tue, 05 Sep 2017 11:28:57 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.84_2) (envelope-from ) id 1dpC2K-0002WK-I4 for pgsql-performance@arkaria.postgresql.org; Tue, 05 Sep 2017 11:28:56 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.84_2) (envelope-from ) id 1dpC2I-0002W0-SW for pgsql-performance@postgresql.org; Tue, 05 Sep 2017 11:28:54 +0000 Received: from mail-wm0-x235.google.com ([2a00:1450:400c:c09::235]) by magus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.84_2) (envelope-from ) id 1dpC2A-0007zq-Fl for pgsql-performance@postgresql.org; Tue, 05 Sep 2017 11:28:53 +0000 Received: by mail-wm0-x235.google.com with SMTP id 187so17639644wmn.1 for ; Tue, 05 Sep 2017 04:28:46 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=mime-version:in-reply-to:references:from:date:message-id:subject:to :cc; bh=vrpMPOYQZh7cpMJ+9pxCllSaTiI5mGzauVm2RHEb+iE=; b=r014NWYvqo6uVE/yEUyNkWFPUH5TpcBLXBcD2WVaM++81ODsNNuSJUOGKwD/Xee4mK RpbqLtQuQOoDi0x2yff8snzLQzzj5jl6g6w98Q6jBkc5OHJ/fV4bixMNoSOkcjLcp8Fc eBYOPG9BEUccuSpmFUbj2fd/ra9ecGhdI7MzTGYt6AMvr9dROFp13vEGBe4htWiAy4qz KbEeERhzlXG9JhML0o2HqZ2+zJYinCV4jeEYqZ4rbXSLmeP+jueJay9jQYSJJGr/KhK+ Scfg9e5FIxlOAXn/7b0O0qpV5wfonypmNquzITAY+whjEO9YoLUWmGxt6lSfK8DCPlSy eKaQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:in-reply-to:references:from:date :message-id:subject:to:cc; bh=vrpMPOYQZh7cpMJ+9pxCllSaTiI5mGzauVm2RHEb+iE=; b=gKcQDW1d+c7NWtxOyV+FI/RXFN72YM/R1gyWbN4VTnRiq1pzOIpwRMR9vZCcgurEtK UwJot2w/kGQOl07Qbv9c2pqVSY7oOScBEBoUwzKSOZIijViMElu77KE47iod7UMtdR1w 2GVwkZDL7kvUs/Q+hp/7/WO497Soba+PfqTcrkXzu3FyZHRv8Z1s/Pa1mj+RefoIyzV/ Hln06TIVDE9o6hWIcCo0n3LanmG5ASte1T80QvXvCGlSun8P7R82Px4mzsB6Ao4iUJuN sHV0lUipeVmGipJ/drOExf6mkhZJTkyYfxvXCF2pLP+EpiESYVQpJafOwWxl/KvprPod 6XiQ== X-Gm-Message-State: AHPjjUivsWXiYKT/uwgucV6WPY67N4YNKDSFYIgiKz+YK8QtPY9JgS4H 0Z6SB4nDNT916V/kKx3bLtybxUIxeQ== X-Google-Smtp-Source: ADKCNb6kI2KDWgdyajwafy0A2T/377/UAQmMGoiqbqMQZm5NN8dLmJHJQ5+tfh9IC+WdjnXcaL/DJYG8qXCegiLDyuI= X-Received: by 10.28.225.132 with SMTP id y126mr2298245wmg.119.1504610924861; Tue, 05 Sep 2017 04:28:44 -0700 (PDT) MIME-Version: 1.0 Received: by 10.28.144.139 with HTTP; Tue, 5 Sep 2017 04:28:44 -0700 (PDT) In-Reply-To: <634f2eb6-daf6-6314-e6f5-1b531b50a9ec@comcast.net> References: <634f2eb6-daf6-6314-e6f5-1b531b50a9ec@comcast.net> From: Mariel Cherkassky Date: Tue, 5 Sep 2017 14:28:44 +0300 Message-ID: Subject: Re: printing results of query to file in different times To: George Neuner Cc: pgsql-performance@postgresql.org Content-Type: multipart/alternative; boundary="001a114b14cab3a0b705586f8759" List-Archive: List-Help: List-ID: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: X-Mailing-List: pgsql-performance Precedence: bulk Sender: pgsql-performance-owner@postgresql.org --001a114b14cab3a0b705586f8759 Content-Type: text/plain; charset="UTF-8" I'm using an extension that is called orafce. Yes I add the raise notice in order to see what happening but it doesnt work faster. The execution plan isnt relevant because It happens for many queries not for a specific one. I didnt understand what do you mean by REPEATABLE_READ . 2017-08-31 16:24 GMT+03:00 George Neuner : > On Thu, 24 Aug 2017 16:15:19 +0300, Mariel Cherkassky < > mariel.cherkassky@gmail.com> wrote: > > >I'm trying to understand what postgresql doing in an issue that I'm > having. > >Our app team wrote a function that runs with a cursor over the results of > a > >query and via the utl_file func they write some columns to a file. I dont > >understand why, but postgresql write the data into the file in the fs in > >parts. I mean that it runs the query and it takes time to get back results > >and when I see that the results back postgresql write to file the data and > >then suddenly stops for X minutes. After those x minutes it starts again > to > >write the data and it continues that way until its done. The query returns > >total *100* rows. I want to understand why it stops suddenly. There arent > > >any locks in the database during this operation. > > > >my function looks like that : > > > >func(a,b,c...) > >cursor cr for > >select ab,c,d,e..... > >begin > >raise notice - 'starting loop time - %',timeofday(); > > for cr_record in cr > > Raise notice 'print to file - '%',timeofday(); > > utl_file.write(file,cr_record) > > end loop > >end > > > >I see the log of the running the next output : > > > >starting loop 16:00 > >print to file : 16:03 > >print to file : 16:03 > >print to file : 16:07 > >print to file : 16:07 > >print to file : 16:07 > >print to file : 16:010 > > > >...... > > > >Can somebody explain to me this kind of behavior ? Why is it taking some > >much time to write and in different minutes after the query already been > >executed and finished ? Mybe I'm getting from the cursor only part of the > >rows ? > > > First I'd ask where did you get utl_file from? Postrgesql has no such > facility, so you must be using an extension. And not one I'm familiar with > either - EnterpriseDB has a utl_file implementation in their Oracle > compatibility stuff, but it uses "get" and "put" calls rather than "read" > and "write". > > Second, raising notices can be slow - I assume you added them to see what > was happening? How does the execution time compare if you remove them? > > I saw someone else asked about the execution plan, but I'm not sure that > will help here because it would affect only the initial select ... the > cursor would be working with the result set and should be able to skip > directly to the target rows. I might expect several seconds for the loop > with I/O ... but certainly not minutes unless the server is severely > overloaded. > > One thing you might look at is the isolation level of the query. If you > are using READ_COMMITTED or less, and the table is busy, other writing > queries may be stepping on yours and even potentially changing your result > set during the cursor loop. I would try using REPEATABLE_READ and see what > happens. > > > George > > > -- > Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) > To make changes to your subscription: > http://www.postgresql.org/mailpref/pgsql-performance > --001a114b14cab3a0b705586f8759 Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable
I'm using an extension that is called= =C2=A0orafce.=C2=A0
Yes I add the raise notice in ord= er to see what happening but it doesnt work faster. The execution plan isnt= relevant because It happens for many queries not for a specific one. I did= nt understand what do you mean by=C2=A0REP= EATABLE_READ=C2=A0.

2017-08-31 16:24 GMT+03:00 George Neuner <gneuner2@comcast.net= >:
On Thu, 2= 4 Aug 2017 16:15:19 +0300, Mariel Cherkassky <mariel.cherkassky@gmail.com> = wrote:

>I'm trying to understand what postgresql doing in an issue that I&#= 39;m having.
>Our app team wrote a function that runs with a cursor over the results = of a
>query and via the utl_file func they write some columns to a file. I do= nt
>understand why, but postgresql write the data into the file in the fs i= n
>parts. I mean that it runs the query and it takes time to get back resu= lts
>and when I see that the results back postgresql write to file the data = and
>then suddenly stops for X minutes. After those x minutes it starts agai= n to
>write the data and it continues that way until its done. The query retu= rns
 >total *100* rows. I want to understand why it stops suddenly. There are= nt

>any locks in the database during this operation.
>
>my function looks like that :
>
>func(a,b,c...)
>cursor cr for
>select ab,c,d,e.....
>begin
>raise notice - 'starting loop time - %',timeofday();
> for cr_record in cr
>=C2=A0=C2=A0=C2=A0 Raise notice 'print to file - '%',timeof= day();
>=C2=A0=C2=A0=C2=A0 utl_file.write(file,cr_record)
> end loop
>end
>
>I see the log of the running the next output :
>
>starting loop 16:00
>print to file : 16:03
>print to file : 16:03
>print to file : 16:07
>print to file : 16:07
>print to file : 16:07
>print to file : 16:010
>
>......
>
>Can somebody explain to me this kind of behavior ? Why is it taking som= e
>much time to write and in different minutes after the query already bee= n
>executed and finished ? Mybe I'm getting from the cursor only part = of the
>rows ?


First I'd ask where did you get=C2=A0 utl_file=C2=A0 from?=C2=A0 Postrg= esql has no such facility, so you must be using an extension.=C2=A0 And not= one I'm familiar with either -=C2=A0 EnterpriseDB has a utl_file imple= mentation in their Oracle compatibility stuff, but it uses "get" = and "put" calls rather than "read" and "write"= ;.

Second, raising notices can be slow - I assume you added them to see what w= as happening?=C2=A0 How does the execution time compare if you remove them?=

I saw someone else asked about the execution plan, but I'm not sure tha= t will help here because it would affect only the initial select ... the cu= rsor would be working with the result set and should be able to skip direct= ly to the target rows.=C2=A0 I might expect several seconds for the loop wi= th I/O ... but certainly not minutes unless the server is severely overload= ed.

One thing you might look at is the isolation level of the query.=C2=A0 If y= ou are using READ_COMMITTED or less, and the table is busy, other writing q= ueries may be stepping on yours and even potentially changing your result s= et during the cursor loop.=C2=A0 I would try using REPEATABLE_READ and see = what happens.


George


--
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-pe= rformance

--001a114b14cab3a0b705586f8759--