Thread: Strange slow behavior in backend

I have a schema that splits large files into tuple-sized bites and stores them in a table.  This was done before TOAST in order to store large files.

I have a backend TCL function that re-assembles the file like this:

-- Fetch the specified document data, reassembling the bits back together
-- in the right order.
-- Calling sequence: cont_doc_fetch(crt_by,crt_date,ctype)
create function cont_doc_fetch(int4,timestamp,varchar) returns text as '
    set odata {}
    spi_exec -array d "select data from cont_doc_data where crt_by = \'$1\' and crt_date = \'$2\' and ctype = \'[quote $3]\' order by seq" {
        append odata $d(data)
    }
    return $odata
    ' LANGUAGE 'pltcl';

This worked great until I put a real big file in (about 5M).  Then, when I tried to fetch the file, it seemed really slow (about 60 seconds).  I tried reassembling the file in the frontend instead and my time dropped to about 6 seconds using this TCL fragment (mpg::qlist is an interface to pg_exec that returns a list of tuples):

    set data {}
    set tuple_list [mpg::qlist "select data from $ca(prefix)_doc_data where crt_by = $crt_by and crt_date = '$crt_date' and ctype = '$ctype' order by seq"]
    foreach rec $tuple_list {
        append data [lindex $rec 0]
    }

The only difference I can identify is whether the re-assembly TCL code is running as a procedural language (backend) or in the frontend.  Anyone have any idea why the difference is so dramatic?

Jan:
Is this the difference between old TCL and new TCL (with multi-port objects)?  Or is there something else about the way the backend handles large chunks of data that would mark the difference?

Kyle <kyle@actarg.com> writes:
> This worked great until I put a real big file in (about 5M).  Then, when
> I tried to fetch the file, it seemed really slow (about 60 seconds).  I
> tried reassembling the file in the frontend instead and my time dropped
> to about 6 seconds using this TCL fragment (mpg::qlist is an interface
> to pg_exec that returns a list of tuples):
> The only difference I can identify is whether the re-assembly TCL code
> is running as a procedural language (backend) or in the frontend.
> Anyone have any idea why the difference is so dramatic?

I happened to have handy a 7.1 backend compiled for profiling, so I
looked into this a little.  I confirm that this seems unreasonably slow.
As near as I can tell, 98% of the backend runtime is being spent in 
strlen() and strcpy() invoked from Tcl_SetResult invoked from Tcl_Eval
invoked from the per-result-tuple loop in pltcl_SPI_exec.  Apparently,
all this is happening because Tcl_Eval thinks it needs to make the
result of the append command available for its caller.  I changed the
inner loop to

spi_exec -array d "select data from pg_largeobject where
loid = $1 order by pageno" {
append odata $d(data);
set z z
}

and voila, the runtime dropped to something reasonable.

So, yes, it would seem that some care in the inner loop of
pltcl_SPI_exec would help a lot.  It'd be worth if'defing the Tcl_Eval
call there to use a new-style call when using Tcl 8.  (This could also
avoid repetitive parsing of the loop body.)  Might want to think about
the same for the Tcl function as a whole, too.

I was also distressed to notice that pltcl_set_tuple_values does a LOT
of repetitive work --- it should be fixed so that the syscache and
function lookups are done only once, not once per tuple.
        regards, tom lane

Tom Lane wrote:
> Kyle <kyle@actarg.com> writes:
> > This worked great until I put a real big file in (about 5M).  Then, when
> > I tried to fetch the file, it seemed really slow (about 60 seconds).  I
> > tried reassembling the file in the frontend instead and my time dropped
> > to about 6 seconds using this TCL fragment (mpg::qlist is an interface
> > to pg_exec that returns a list of tuples):
> > The only difference I can identify is whether the re-assembly TCL code
> > is running as a procedural language (backend) or in the frontend.
> > Anyone have any idea why the difference is so dramatic?
>
> I happened to have handy a 7.1 backend compiled for profiling, so I
> looked into this a little.  I confirm that this seems unreasonably slow.
> As near as I can tell, 98% of the backend runtime is being spent in
> strlen() and strcpy() invoked from Tcl_SetResult invoked from Tcl_Eval
> invoked from the per-result-tuple loop in pltcl_SPI_exec.  Apparently,
> all this is happening because Tcl_Eval thinks it needs to make the
> result of the append command available for its caller.  I changed the
> inner loop to
>
> spi_exec -array d "select data from pg_largeobject where
> loid = $1 order by pageno" {
> append odata $d(data);
> set z z
> }
>
> and voila, the runtime dropped to something reasonable.
>
> So, yes, it would seem that some care in the inner loop of
> pltcl_SPI_exec would help a lot.  It'd be worth if'defing the Tcl_Eval
> call there to use a new-style call when using Tcl 8.  (This could also
> avoid repetitive parsing of the loop body.)  Might want to think about
> the same for the Tcl function as a whole, too.
>
> I was also distressed to notice that pltcl_set_tuple_values does a LOT
> of repetitive work --- it should be fixed so that the syscache and
> function lookups are done only once, not once per tuple.
   Hmmm - seems worse than I thought.
   Again,  let's  wait  with  all  that until we can overhaul it   including the tupleset  return  mechanism  and
simply loose   pre-8.0 compatibility.
 


Jan

--

#======================================================================#
# It's easier to get forgiveness for being wrong than for being right. #
# Let's break this rule - forgive me.                                  #
#================================================== JanWieck@Yahoo.com #

Kyle wrote:
> I'm using 7.0.1 with a TCL frontend.
>
> I have a schema that splits large files into tuple-sized bites and
> stores them in a table.  This was done before TOAST in order to store
> large files.
>
> I have a backend TCL function that re-assembles the file like this:
>
> -- Fetch the specified document data, reassembling the bits back
> together
> -- in the right order.
> -- Calling sequence: cont_doc_fetch(crt_by,crt_date,ctype)
> create function cont_doc_fetch(int4,timestamp,varchar) returns text as '
>
>     set odata {}
>     spi_exec -array d "select data from cont_doc_data where crt_by =
> \'$1\' and crt_date = \'$2\' and ctype = \'[quote $3]\' order by seq" {
>         append odata $d(data)
>     }
>     return $odata
>     ' LANGUAGE 'pltcl';
>
> This worked great until I put a real big file in (about 5M).  Then, when
> I tried to fetch the file, it seemed really slow (about 60 seconds).  I
> tried reassembling the file in the frontend instead and my time dropped
> to about 6 seconds using this TCL fragment (mpg::qlist is an interface
> to pg_exec that returns a list of tuples):
>
>     set data {}
>     set tuple_list [mpg::qlist "select data from $ca(prefix)_doc_data
> where crt_by = $crt_by and crt_date = '$crt_date' and ctype = '$ctype'
> order by seq"]
>     foreach rec $tuple_list {
>         append data [lindex $rec 0]
>     }
>
> The only difference I can identify is whether the re-assembly TCL code
> is running as a procedural language (backend) or in the frontend.
> Anyone have any idea why the difference is so dramatic?
>
> Jan:
> Is this the difference between old TCL and new TCL (with multi-port
> objects)?  Or is there something else about the way the backend handles
> large chunks of data that would mark the difference?
   That's  it.  It  shouldn't have to do with the amount of data   invoked, but with the number of tuples returned  by
spi_exec  and spi_execp commands.
 
   Due  to  backwards  compatibility, all commands in the PL/Tcl   handler  still  use  the  old  string  interface.
Thus, the   procedure  text  for  each  tuple (in your case "append odata   $d(data)") is evaluated from it's string
representationagain   and  again,  needs to be interpreted and precompiled for each   single tuple by the Tcl
interpreter.I think using  Tcl_Obj's   here would cause a substantial improvement.
 
   I  plan  to  do  a  major overhaul of PL/Tcl after we have an   interface for  functions  returning  tuple  sets.
This will   include   loosing   the  backward  compatibility  to  pre-8.0   releases of Tcl because of using the
Tcl_Objinterface  only.
 


Jan

--

#======================================================================#
# It's easier to get forgiveness for being wrong than for being right. #
# Let's break this rule - forgive me.                                  #
#================================================== JanWieck@Yahoo.com #