Re: Large arrays give long lag on server side before command executes - Mailing list pgsql-general

Probably should have added the prototypes:

-- the prepared statement
prepare maint_status_recursive(text, integer[], character(32)[],
character(32)[], text[], integer[], bytea[])
    as select * from maint_status_recursive($1,$2,$3,$4,$5,$6,$7);

-- the stored procedure
create or replace function maint_status_recursive(text, integer[],
character(32)[], character(32)[], text[], integer[], bytea[]) returns
setof maint_status_type language plpgsql

Looking at the processes on the machine, I see the process doing BIND
during those seconds.

As mentioned, I'm sending 1200 element arrays as all the array
parameters, and the parsing is taking an amazing 5+ second on an
unloaded server... it is a 300Mhz Mandrake server, but still seems
extreme with 5+ seconds parsing and building a some arrays.

I'd really thankful for pointers to solutions or code to look at.

d.
--
David Helgason,
Business Development et al.,
Over the Edge I/S (http://otee.dk)
Direct line +45 2620 0663
Main line +45 3264 5049

On 24. sep 2004, at 11:09, David Helgason wrote:

> I'm calling one stored procedure with a prepared statement on the
> server with 6 arrays of around 1200 elements each as parameters. The
> parameters are around 220K in total.
>
> This is taking a surprising amount of time. Thus I put a lot of
> logging into the application and in the stored procedure that's
> getting called. It seems that almost all of most of the time is spent
> before the stored procedure is even entered.
>
> What wakes my suspicion that this is not as it should be, is that the
> time spent before the prepared statements starts is as long or longer
> as the time spent inside the stored procedure: doing 1200 inserts into
> a table, a fairly complex outer join with that data, and a loop over
> around the 1200 resulting records.
>
> Enabling lots of logging gives me:
>
> 2004-09-22 20:27:29 [5812] LOG:  REWRITER STATISTICS
> DETAIL:  ! system usage stats:
>         !       0.000004 elapsed 0.000000 user 0.000000 system sec
>         !       [11.850198 user 0.215967 sys total]
>         !       0/0 [0/0] filesystem blocks in/out
>         !       0/0 [0/3001] page faults/reclaims, 0 [0] swaps
>         !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
>         !       0/0 [132/209] voluntary/involuntary context switches
>         ! buffer usage stats:
>         !       Shared blocks:          0 read,          0 written,
> buffer hit rate = 0.00%
>         !       Local  blocks:          0 read,          0 written,
> buffer hit rate = 0.00%
>         !       Direct blocks:          0 read,          0 written
> 2004-09-22 20:27:29 [5812] DEBUG:  ProcessUtility
> 2004-09-22 20:27:29 [5812] DEBUG:  CommitTransactionCommand
> 2004-09-22 20:27:29 [5812] LOG:  duration: 1.982 ms
> 2004-09-22 20:27:30 [5812] DEBUG:  StartTransactionCommand
> 2004-09-22 20:27:35 [5812] NOTICE:  Recursive status for begun at
> 2004-09-22 20:27:35.371659
> 2004-09-22 20:27:39 [5812] LOG:  PARSER STATISTICS
> DETAIL:  ! system usage stats:
>         !       0.000119 elapsed 0.000000 user 0.000000 system sec
>         !       [20.825833 user 0.340948 sys total]
>         !       0/0 [0/0] filesystem blocks in/out
>         !       0/0 [0/3590] page faults/reclaims, 0 [0] swaps
>         !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
>         !       0/0 [273/362] voluntary/involuntary context switches
>         ! buffer usage stats:
>         !       Shared blocks:          0 read,          0 written,
> buffer hit rate = 0.00%
>         !       Local  blocks:          0 read,          0 written,
> buffer hit rate = 0.00%
>         !       Direct blocks:          0 read,          0 written
> CONTEXT:  SQL function "get_asset_guid_safe" during startup
>         PL/pgSQL function "maint_status_recursive" line 198 at
> assignment
>
> What I find interesting is how five seconds pass from the 20:27:30
> debug, where it starts calling my procedure, and the log I print out,
> at the top of the procedure at 20:27:35.
>
> Any suggestions how I go about finding the bottleneck here? What tools
> do other people use for profiling on Linux.
>
> This might sound like a "then don't do that" situation. The data is
> stuff that will be inserted into a temporary table, so I'd rather not
> go a different route, but I'm considering switching to a lot of insert
> statements or a copy in.
>
> Regards,
>
> d.
> --
> David Helgason,
> Business Development et al.,
> Over the Edge I/S (http://otee.dk)
> Direct line +45 2620 0663
> Main line +45 3264 5049
>
>
> ---------------------------(end of
> broadcast)---------------------------
> TIP 7: don't forget to increase your free space map settings
>