Re: Slow update

Filip Rembiałkowski wrote:

>
> 2009/1/21 Herouth Maoz <herouth(at)unicell(dot)co(dot)il
> <mailto:herouth(at)unicell(dot)co(dot)il>>
>
> Hello.
>
> I have a daily process that synchronizes our reports database from
> our production databases. In the past few days, it happened a
> couple of times that an update query took around 7-8 hours to
> complete, which seems a bit excessive. This is the query:
>
> UPDATE rb
> SET service = b.service,
> status = b.status,
> has_notification = gateway_id NOT IN (4,101,102),
> operator = COALESCE(
> b.actual_target_network_id,
> b.requested_target_network_id
> )
> FROM sms.billing b
> WHERE b.time_arrived >= :date_start
> AND rb.time_stamp >= :date_start
> AND rb.delivered = 0
> AND rb.sms_user = b.user_id
> AND rb.reference = b.user_reference
> AND OVERLAY( rb.msisdn placing '972' from 1 for 1 ) = b.msisdn
> AND NOT mo_billed
> AND system_id <> 6 -- Exclude Corporate, as it aleady has
> service/status
> ;
>
> The variable ":date_start" is set to a date 3 days ago.
>
> I ran explain for this query and it gave me this:
>
>
> --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
> Nested Loop (cost=21567.12..854759.82 rows=1 width=210)
> Join Filter: (((rb.sms_user)::text = (b.user_id)::text) AND
> (rb.reference = b.user_reference))
> -> Bitmap Heap Scan on rb (cost=21546.02..23946.16 rows=819
> width=198)
> Recheck Cond: ((delivered = 0) AND (time_stamp >=
> '2009-01-18 00:00:00'::timestamp without time zone) AND
> (time_stamp < '2009-01-21 00:00:00'::timestamp without time zone))
> Filter: ((NOT mo_billed) AND (system_id <> 6))
> -> BitmapAnd (cost=21546.02..21546.02 rows=819 width=0)
> -> Bitmap Index Scan on rb_delivered_ind
> (cost=0.00..1419.99 rows=45768 width=0)
> Index Cond: (delivered = 0)
> -> Bitmap Index Scan on rb_timestamp_ind
> (cost=0.00..20125.37 rows=188994 width=0)
> Index Cond: ((time_stamp >= '2009-01-18
> 00:00:00'::timestamp without time zone) AND (time_stamp <
> '2009-01-21 00:00:00'::timestamp without time zone))
> -> Bitmap Heap Scan on billing b (cost=21.10..1004.77
> rows=351 width=49)
> Recheck Cond: ((b.msisdn)::text =
> (("substring"((rb.msisdn)::text, 1, 0) || '972'::text) ||
> "substring"((rb.msisdn)::text, 2)))
> Filter: ((b.time_arrived >= '2009-01-18
> 00:00:00'::timestamp without time zone) AND (b.time_arrived <
> '2009-01-21 00:00:00'::timestamp without time zone))
> -> Bitmap Index Scan on billing_msisdn_sme_reference
> (cost=0.00..21.10 rows=351 width=0)
> Index Cond: ((b.msisdn)::text =
> (("substring"((rb.msisdn)::text, 1, 0) || '972'::text) ||
> "substring"((rb.msisdn)::text, 2)))
>
> I'm not an expert on reading plans, but it seems to me that it
> uses indices on both tables that participate in this query, so it
> shouldn't take such a long time.
>
> The number of records in the table rb for the past three days is
> 386833. On the sms.billing table it seems to select the index on
> the msisdn and sme_reference fields and use it partially (only
> using the msisdn field). Looking at that table, the frequency of
> each value in the msisdn field is at most 17678 for the current
> data, where mostly it's a couple of thousands. How can this take
> so long?
>
>
> 1. which postgres version?
> 2. can you post results of EXPLAIN ANALYZE (please note it actually
> executes the query)?
I'm sorry it took some time to answer these questions - as I explained,
I needed an opportunity to make the change in our production machine
since the data in the development machine wouldn't do at all.

So the answer is PostgreSQL v. 8.3.1. The output of explain analyze is
at the end of this message. Note that the run started at 04:20:50, and
finished at 11:29:30. Also, a full vacuum was ran on the entire database
a day before, and I run analyze on each table whenever there is a bulk
insert or update to it - and the only way data comes in is in bulks.

Could the delay have anything to do with disk space? The device where
the database is located has around 3G left (98% full). If that's the
problem, I suppose I can add a table space on another device and move
the four largest tables into it, but if it has nothing to do with it,
i'd rather stay on the one device. The machine has 4G of RAM.

I hope someone can clue me in based on the results of explain analyze.

Herouth

QUERY PLAN

------------------------------------------------------------------------------------------------------------------
------------------------------------------
Nested Loop (cost=27968.36..645009.77 rows=1 width=210) (actual
time=57128.573..25674240.262 rows=166844 loops=1
)
Join Filter: (((rb.sms_user)::text = (b.user_id)::text) AND
(rb.reference = b.user_reference))
-> Bitmap Heap Scan on rb (cost=27943.66..29556.78 rows=549
width=198) (actual time=37105.248..54856.430 rows
=151332 loops=1)
Recheck Cond: ((delivered = 0) AND (time_stamp >= '2009-02-06
00:00:00'::timestamp without time zone))
Filter: ((NOT mo_billed) AND (system_id <> 6))
-> BitmapAnd (cost=27943.66..27943.66 rows=549 width=0)
(actual time=37049.818..37049.818 rows=0 loops=
1)
-> Bitmap Index Scan on rb_delivered_ind
(cost=0.00..884.99 rows=24367 width=0) (actual time=8147
.209..8147.209 rows=871142 loops=1)
Index Cond: (delivered = 0)
-> Bitmap Index Scan on rb_timestamp_ind
(cost=0.00..27058.14 rows=235424 width=0) (actual time=2
8884.578..28884.578 rows=1333295 loops=1)
Index Cond: (time_stamp >= '2009-02-06
00:00:00'::timestamp without time zone)
-> Bitmap Heap Scan on billing b (cost=24.70..1110.35 rows=389
width=49) (actual time=165.740..169.260 rows=1
0 loops=151332)
Recheck Cond: ((b.msisdn)::text =
(("substring"((rb.msisdn)::text, 1, 0) || '972'::text) || "substring"((
rb.msisdn)::text, 2)))
Filter: (b.time_arrived >= '2009-02-06 00:00:00'::timestamp
without time zone)
-> Bitmap Index Scan on billing_msisdn_sme_reference
(cost=0.00..24.70 rows=389 width=0) (actual time=2
1.418..21.418 rows=252 loops=151332)
Index Cond: ((b.msisdn)::text =
(("substring"((rb.msisdn)::text, 1, 0) || '972'::text) || "substrin
g"((rb.msisdn)::text, 2)))
Total runtime: 25720210.772 ms
(16 rows)