Обсуждение: Slow Query
Hello, I have a recurring script that updates some tables from an MS_SQL server. One of the operations sets a field in all records to null in preparation of being updated with values from the other server. The SQL statement is: update shawns_data set alias = null; Alias is a type varchar(8) The table has 26 fields per record and there are about 15,700 records. The server hardware is a dual QUAD-CORE Intel 2 GHz XEON dell 2950 server with 4 drive SAS RAID-5 array, and 16G of RAM. The OS is Slackware 11 with some updatews and Postgres v8.2.4 built from source. Even after VACUUM this simple line takes 35 sec to complete. Other more complicated deletes and updates, some of the tables in this database are over 300 million records, take as much time as this simple query. My question: Is there a better, ie. faster, way to do this task? Shawn
Shawn <postgres@xmtservices.net> writes:
> update shawns_data set alias = null;
> Alias is a type varchar(8)
> The table has 26 fields per record and there are about 15,700
> records. The server hardware is a dual QUAD-CORE Intel 2 GHz XEON dell
> 2950 server with 4 drive SAS RAID-5 array, and 16G of RAM. The OS is
> Slackware 11 with some updatews and Postgres v8.2.4 built from source.
> Even after VACUUM this simple line takes 35 sec to complete.
Seems like a lot. Table bloat maybe (what does VACUUM VERBOSE say about
this table)? An unreasonably large number of indexes to update?
Foreign key checks? (Though unless you have FKs pointing at alias,
I'd think 8.2 would avoid needing to make any FK checks.)
Could we see EXPLAIN ANALYZE output for this operation? (If you don't
really want to zap the column right now, wrap the EXPLAIN in
BEGIN/ROLLBACK.)
regards, tom lane
Hi Tom, Thanks for replying. There are no FK's, indexes, or dependents on the alias field. The system is in the middle of its weekly full activity log resync, about 600 Million records. It will be done later this evening and I will run the explain analyze thenand I will post the results. I will also run a vacuum full analyze on it before the run and have timing on. Shawn On Sat, 01 Sep 2007 14:09:54 -0400 Tom Lane <tgl@sss.pgh.pa.us> wrote: > Shawn <postgres@xmtservices.net> writes: > > update shawns_data set alias = null; > > > Alias is a type varchar(8) > > > The table has 26 fields per record and there are about 15,700 > > records. The server hardware is a dual QUAD-CORE Intel 2 GHz XEON > > dell 2950 server with 4 drive SAS RAID-5 array, and 16G of RAM. > > The OS is Slackware 11 with some updatews and Postgres v8.2.4 built > > from source. > > > Even after VACUUM this simple line takes 35 sec to complete. > > Seems like a lot. Table bloat maybe (what does VACUUM VERBOSE say > about this table)? An unreasonably large number of indexes to update? > Foreign key checks? (Though unless you have FKs pointing at alias, > I'd think 8.2 would avoid needing to make any FK checks.) > > Could we see EXPLAIN ANALYZE output for this operation? (If you don't > really want to zap the column right now, wrap the EXPLAIN in > BEGIN/ROLLBACK.) > > regards, tom lane > > ---------------------------(end of > broadcast)--------------------------- TIP 6: explain analyze is your > friend >
Ok,
The query just ran and here is the basic output:
UPDATE 15445
Time: 22121.141 ms
and
explain ANALYZE update shawns_data set alias = null;
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------
Seq Scan on shawns_data (cost=0.00..465.45 rows=15445 width=480) (actual time=0.034..67.743 rows=15445 loops=1)
Total runtime: 1865.002 ms
(2 rows)
Shawn
On Sat, 1 Sep 2007 13:18:16 -0700
Shawn <postgres@xmtservices.net> wrote:
>
> Hi Tom,
>
> Thanks for replying.
>
> There are no FK's, indexes, or dependents on the alias field.
>
> The system is in the middle of its weekly full activity log resync,
> about 600 Million records. It will be done later this evening and I
> will run the explain analyze thenand I will post the results. I will
> also run a vacuum full analyze on it before the run and have timing
> on.
>
> Shawn
>
>
> On Sat, 01 Sep 2007 14:09:54 -0400 Tom Lane
> <tgl@sss.pgh.pa.us> wrote:
>
> > Shawn <postgres@xmtservices.net> writes:
> > > update shawns_data set alias = null;
> >
> > > Alias is a type varchar(8)
> >
> > > The table has 26 fields per record and there are about 15,700
> > > records. The server hardware is a dual QUAD-CORE Intel 2 GHz XEON
> > > dell 2950 server with 4 drive SAS RAID-5 array, and 16G of RAM.
> > > The OS is Slackware 11 with some updatews and Postgres v8.2.4
> > > built from source.
> >
> > > Even after VACUUM this simple line takes 35 sec to complete.
> >
> > Seems like a lot. Table bloat maybe (what does VACUUM VERBOSE say
> > about this table)? An unreasonably large number of indexes to
> > update? Foreign key checks? (Though unless you have FKs pointing
> > at alias, I'd think 8.2 would avoid needing to make any FK checks.)
> >
> > Could we see EXPLAIN ANALYZE output for this operation? (If you
> > don't really want to zap the column right now, wrap the EXPLAIN in
> > BEGIN/ROLLBACK.)
> >
> > regards, tom lane
> >
> > ---------------------------(end of
> > broadcast)--------------------------- TIP 6: explain analyze is your
> > friend
> >
>
> ---------------------------(end of
> broadcast)--------------------------- TIP 1: if posting/reading
> through Usenet, please send an appropriate subscribe-nomail command
> to majordomo@postgresql.org so that your message can get through to
> the mailing list cleanly
>
Shawn <postgres@xmtservices.net> writes:
> The query just ran and here is the basic output:
> UPDATE 15445
> Time: 22121.141 ms
> and
> explain ANALYZE update shawns_data set alias = null;
> QUERY PLAN
> -----------------------------------------------------------------------------------------------------------------
> Seq Scan on shawns_data (cost=0.00..465.45 rows=15445 width=480) (actual time=0.034..67.743 rows=15445 loops=1)
> Total runtime: 1865.002 ms
> (2 rows)
Hmmm ... did you run the real query and the EXPLAIN in immediate
succession? If so, the only reason I can think of for the speed
difference is that all the rows were fetched already for the second
run. Which doesn't make a lot of sense given the hardware specs
you mentioned. Try watching "vmstat 1" and see if there's some
noticeable difference in the behavior.
regards, tom lane
>>> On Sat, Sep 1, 2007 at 12:29 PM, in message <20070901102947.0c0a50a3@boffin.xmtservices.net>, Shawn <postgres@xmtservices.net> wrote: > update shawns_data set alias = null; > Even after VACUUM this simple line takes 35 sec to complete. Would any rows already have a null alias when you run this? If so, try adding 'where alias is not null' to the query. -Kevin
Thanks Kevin, This one initially added about 10sec to the run but I added a HASH index on the alias field and its now about 5 sec average runtime, a net improvement. Shawn On Sun, 02 Sep 2007 10:49:09 -0500 "Kevin Grittner" <Kevin.Grittner@wicourts.gov> wrote: > >>> On Sat, Sep 1, 2007 at 12:29 PM, in message > <20070901102947.0c0a50a3@boffin.xmtservices.net>, Shawn > <postgres@xmtservices.net> wrote: > > update shawns_data set alias = null; > > Even after VACUUM this simple line takes 35 sec to complete. > > Would any rows already have a null alias when you run this? > > If so, try adding 'where alias is not null' to the query. > > -Kevin > > > > > ---------------------------(end of > broadcast)--------------------------- TIP 2: Don't 'kill -9' the > postmaster >
On Sat, 01 Sep 2007 23:00:10 -0400
Tom Lane <tgl@sss.pgh.pa.us> wrote:
> Shawn <postgres@xmtservices.net> writes:
> > The query just ran and here is the basic output:
>
> > UPDATE 15445
> > Time: 22121.141 ms
>
> > and
>
> > explain ANALYZE update shawns_data set alias = null;
> > QUERY
> > PLAN
> > -----------------------------------------------------------------------------------------------------------------
> > Seq Scan on shawns_data (cost=0.00..465.45 rows=15445 width=480)
> > (actual time=0.034..67.743 rows=15445 loops=1) Total runtime:
> > 1865.002 ms (2 rows)
>
> Hmmm ... did you run the real query and the EXPLAIN in immediate
> succession? If so, the only reason I can think of for the speed
> difference is that all the rows were fetched already for the second
> run. Which doesn't make a lot of sense given the hardware specs
> you mentioned. Try watching "vmstat 1" and see if there's some
> noticeable difference in the behavior.
>
Actually no,
The runs were at least an 24 hours apart.
Running the query standalone was quite interesting. There's a lot of
disk output:
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
r b swpd free buff cache si so bi bo in cs us sy id wa
0 0 2580 450992 84420 16007864 0 0 1 1 1 2 3 0 94 2
0 0 2580 450992 84420 16007864 0 0 0 0 1003 18 0 0 100 0
0 0 2580 450660 84420 16007864 0 0 0 6764 1127 202 0 0 100 0
0 0 2580 450660 84420 16007864 0 0 0 0 1004 28 0 0 100 0
0 0 2580 450660 84420 16007864 0 0 0 0 1011 58 0 0 100 0
0 0 2580 450660 84420 16007864 0 0 0 0 1011 50 0 0 100 0
0 0 2580 450660 84428 16007864 0 0 0 32 1011 53 0 0 100 0
0 0 2580 450660 84428 16007864 0 0 0 3034 1095 191 0 0 100 0
0 0 2580 450164 84428 16007864 0 0 0 0 1032 362 0 0 100 0
0 0 2580 450164 84428 16007864 0 0 0 0 1002 22 0 0 100 0
1 0 2580 446444 84428 16012240 0 0 0 2568 1024 398 4 1 95 0
1 0 2580 456172 84428 16001760 0 0 8 11549 1136 616 10 3 87 0
0 0 2580 452164 84428 16005524 0 0 4 26580 1885 1479 4 2 93 1
0 0 2580 452164 84436 16005516 0 0 0 40 1004 26 0 0 100 0
0 0 2580 452164 84436 16005524 0 0 0 0 1001 36 0 0 100 0
0 0 2580 452164 84436 16005524 0 0 0 0 1001 24 0 0 100 0
0 0 2580 452164 84436 16005524 0 0 0 0 1001 36 0 0 100 0
0 0 2580 452164 84436 16005524 0 0 0 3 1005 27 0 0 100 0
0 0 2580 452040 84436 16005524 0 0 0 0 1006 41 0 0 100 0
0 0 2580 452040 84436 16005524 0 0 0 0 1002 20 0 0 100 0
Also it runs a lot faster by itself, so I am thinking there is some query early on that is
really fragmenting the table. Here's the whole script:
\timing
select now();
create temporary table unit_operation(lid varchar(5), hang_time varchar(3),multi_csd_enabled bool,multi_node_enabled
bool,wide_area_enabledbool);
create temporary table unit(lid varchar(5),alias char(8),type smallint);
\copy unit from '/tmp/wc_unit'
\copy unit_operation from '/tmp/wc_unit_operation'
truncate csd;
insert into csd(lid,alias,type) select lid,alias,type from unit;
update csd set hang_time = uo.hang_time, multi_csd_enabled = uo.multi_csd_enabled, multi_node_enabled =
uo.multi_node_enabled,wide_area_enabled = uo.wide_area_enabled from unit_operation uo where csd.lid = uo.lid;
create temporary table groups(lid varchar(5),alias varchar(8));
create temporary table group_operation(lid varchar(15),hang_time varchar(8));
\copy groups from '/tmp/wc_groups'
\copy group_operation from '/tmp/wc_group_operation'
truncate gid;
insert into gid(gid,alias) select lid,alias from groups;
update gid set hang_time = go.hang_time from group_operation go where gid.gid = go.lid;
truncate rc_unit_state;
\copy rc_unit_state from '/tmp/wc_rc_unit_state' with null as ''
update lidrange set csd = false, data = false, disable = false, lost = false;
update lidrange set csd = true from csd where lidrange.lid = csd.lid;
update lidrange set data = true from shawns_data where lidrange.lid = shawns_data.lid;
update lidrange set disable = true from rc_unit_state where lidrange.lid = rc_unit_state.lid;
update shawns_data set alias = null where alias is not null;
update shawns_data set alias = csd.alias from csd where shawns_data.lid = csd.lid;
update lidrange set lost = true from shawns_data where shawns_data.lid = lidrange.lid and shawns_data.lost = true
\i '/home/shawn/vacuum_data.sql'
As you can see there is nothing really accessing the shawns_data table before the query in question.
I have also allocated 380 Megs of RAM to any virtual process, I can't see where any of these tables
could take up this much RAM. Here is my postgresql.conf:
# -----------------------------
# PostgreSQL configuration file
# -----------------------------
#
# This file consists of lines of the form:
#
# name = value
#
# (The '=' is optional.) White space may be used. Comments are introduced
# with '#' anywhere on a line. The complete list of option names and
# allowed values can be found in the PostgreSQL documentation. The
# commented-out settings shown in this file represent the default values.
#
# Please note that re-commenting a setting is NOT sufficient to revert it
# to the default value, unless you restart the server.
#
# Any option can also be given as a command line switch to the server,
# e.g., 'postgres -c log_connections=on'. Some options can be changed at
# run-time with the 'SET' SQL command.
#
# This file is read on server startup and when the server receives a
# SIGHUP. If you edit the file on a running system, you have to SIGHUP the
# server for the changes to take effect, or use "pg_ctl reload". Some
# settings, which are marked below, require a server shutdown and restart
# to take effect.
#
# Memory units: kB = kilobytes MB = megabytes GB = gigabytes
# Time units: ms = milliseconds s = seconds min = minutes h = hours d = days
#---------------------------------------------------------------------------
# FILE LOCATIONS
#---------------------------------------------------------------------------
# The default values of these variables are driven from the -D command line
# switch or PGDATA environment variable, represented here as ConfigDir.
#data_directory = 'ConfigDir' # use data in another directory
# (change requires restart)
#hba_file = 'ConfigDir/pg_hba.conf' # host-based authentication file
# (change requires restart)
#ident_file = 'ConfigDir/pg_ident.conf' # ident configuration file
# (change requires restart)
# If external_pid_file is not explicitly set, no extra PID file is written.
#external_pid_file = '(none)' # write an extra PID file
# (change requires restart)
#---------------------------------------------------------------------------
# CONNECTIONS AND AUTHENTICATION
#---------------------------------------------------------------------------
# - Connection Settings -
#listen_addresses = 'localhost' # what IP address(es) to listen on;
# comma-separated list of addresses;
# defaults to 'localhost', '*' = all
# (change requires restart)
#port = 5432 # (change requires restart)
max_connections = 20 # (change requires restart)
# Note: increasing max_connections costs ~400 bytes of shared memory per
# connection slot, plus lock space (see max_locks_per_transaction). You
# might also need to raise shared_buffers to support more connections.
#superuser_reserved_connections = 3 # (change requires restart)
#unix_socket_directory = '' # (change requires restart)
#unix_socket_group = '' # (change requires restart)
#unix_socket_permissions = 0777 # octal
# (change requires restart)
#bonjour_name = '' # defaults to the computer name
# (change requires restart)
# - Security & Authentication -
#authentication_timeout = 1min # 1s-600s
#ssl = off # (change requires restart)
#password_encryption = on
#db_user_namespace = off
# Kerberos
#krb_server_keyfile = '' # (change requires restart)
#krb_srvname = 'postgres' # (change requires restart)
#krb_server_hostname = '' # empty string matches any keytab entry
# (change requires restart)
#krb_caseins_users = off # (change requires restart)
# - TCP Keepalives -
# see 'man 7 tcp' for details
#tcp_keepalives_idle = 0 # TCP_KEEPIDLE, in seconds;
# 0 selects the system default
#tcp_keepalives_interval = 0 # TCP_KEEPINTVL, in seconds;
# 0 selects the system default
#tcp_keepalives_count = 0 # TCP_KEEPCNT;
# 0 selects the system default
#---------------------------------------------------------------------------
# RESOURCE USAGE (except WAL)
#---------------------------------------------------------------------------
# - Memory -
shared_buffers = 300MB # min 128kB or max_connections*16kB
# (change requires restart)
#temp_buffers = 8MB # min 800kB
#max_prepared_transactions = 5 # can be 0 or more
# (change requires restart)
# Note: increasing max_prepared_transactions costs ~600 bytes of shared memory
# per transaction slot, plus lock space (see max_locks_per_transaction).
work_mem = 300MB # min 64kB
maintenance_work_mem = 260MB # min 1MB
max_stack_depth = 7MB # min 100kB
# - Free Space Map -
max_fsm_pages = 15360000 # min max_fsm_relations*16, 6 bytes each
# (change requires restart)
#max_fsm_relations = 1000 # min 100, ~70 bytes each
# (change requires restart)
# - Kernel Resource Usage -
#max_files_per_process = 1000 # min 25
# (change requires restart)
#shared_preload_libraries = '' # (change requires restart)
# - Cost-Based Vacuum Delay -
#vacuum_cost_delay = 0 # 0-1000 milliseconds
#vacuum_cost_page_hit = 1 # 0-10000 credits
#vacuum_cost_page_miss = 10 # 0-10000 credits
#vacuum_cost_page_dirty = 20 # 0-10000 credits
#vacuum_cost_limit = 200 # 0-10000 credits
# - Background writer -
#bgwriter_delay = 200ms # 10-10000ms between rounds
#bgwriter_lru_percent = 1.0 # 0-100% of LRU buffers scanned/round
#bgwriter_lru_maxpages = 5 # 0-1000 buffers max written/round
#bgwriter_all_percent = 0.333 # 0-100% of all buffers scanned/round
#bgwriter_all_maxpages = 5 # 0-1000 buffers max written/round
#---------------------------------------------------------------------------
# WRITE AHEAD LOG
#---------------------------------------------------------------------------
# - Settings -
#fsync = on # turns forced synchronization on or off
#wal_sync_method = fsync # the default is the first option
# supported by the operating system:
# open_datasync
# fdatasync
# fsync
# fsync_writethrough
# open_sync
#full_page_writes = on # recover from partial page writes
#wal_buffers = 64kB # min 32kB
# (change requires restart)
#commit_delay = 0 # range 0-100000, in microseconds
#commit_siblings = 5 # range 1-1000
# - Checkpoints -
checkpoint_segments = 50 # in logfile segments, min 1, 16MB each
#checkpoint_timeout = 5min # range 30s-1h
#checkpoint_warning = 30s # 0 is off
# - Archiving -
#archive_command = '' # command to use to archive a logfile segment
#archive_timeout = 0 # force a logfile segment switch after this
# many seconds; 0 is off
#---------------------------------------------------------------------------
# QUERY TUNING
#---------------------------------------------------------------------------
# - Planner Method Configuration -
#enable_bitmapscan = on
#enable_hashagg = on
#enable_hashjoin = on
#enable_indexscan = on
#enable_mergejoin = on
#enable_nestloop = on
#enable_seqscan = on
#enable_sort = on
#enable_tidscan = on
# - Planner Cost Constants -
#seq_page_cost = 1.0 # measured on an arbitrary scale
#random_page_cost = 4.0 # same scale as above
#cpu_tuple_cost = 0.01 # same scale as above
#cpu_index_tuple_cost = 0.005 # same scale as above
#cpu_operator_cost = 0.0025 # same scale as above
#effective_cache_size = 128MB
# - Genetic Query Optimizer -
#geqo = on
#geqo_threshold = 12
#geqo_effort = 5 # range 1-10
#geqo_pool_size = 0 # selects default based on effort
#geqo_generations = 0 # selects default based on effort
#geqo_selection_bias = 2.0 # range 1.5-2.0
# - Other Planner Options -
#default_statistics_target = 10 # range 1-1000
#constraint_exclusion = off
#from_collapse_limit = 8
#join_collapse_limit = 8 # 1 disables collapsing of explicit
# JOINs
#---------------------------------------------------------------------------
# ERROR REPORTING AND LOGGING
#---------------------------------------------------------------------------
# - Where to Log -
#log_destination = 'stderr' # Valid values are combinations of
# stderr, syslog and eventlog,
# depending on platform.
# This is used when logging to stderr:
#redirect_stderr = off # Enable capturing of stderr into log
# files
# (change requires restart)
# These are only used if redirect_stderr is on:
#log_directory = 'pg_log' # Directory where log files are written
# Can be absolute or relative to PGDATA
log_filename = 'postgresql-%Y-%m-%d_%H%M%S.log' # Log file name pattern.
# Can include strftime() escapes
log_truncate_on_rotation = off # If on, any existing log file of the same
# name as the new log file will be
# truncated rather than appended to. But
# such truncation only occurs on
# time-driven rotation, not on restarts
# or size-driven rotation. Default is
# off, meaning append to existing files
# in all cases.
#log_rotation_age = 1m # Automatic rotation of logfiles will
# happen after that time. 0 to
# disable.
log_rotation_size = 10MB # Automatic rotation of logfiles will
# happen after that much log
# output. 0 to disable.
# These are relevant when logging to syslog:
#syslog_facility = 'LOCAL0'
#syslog_ident = 'postgres'
# - When to Log -
#client_min_messages = notice # Values, in order of decreasing detail:
# debug5
# debug4
# debug3
# debug2
# debug1
# log
# notice
# warning
# error
#log_min_messages = notice # Values, in order of decreasing detail:
# debug5
# debug4
# debug3
# debug2
# debug1
# info
# notice
# warning
# error
# log
# fatal
# panic
#log_error_verbosity = default # terse, default, or verbose messages
#log_min_error_statement = error # Values in order of increasing severity:
# debug5
# debug4
# debug3
# debug2
# debug1
# info
# notice
# warning
# error
# fatal
# panic (effectively off)
#log_min_duration_statement = -1 # -1 is disabled, 0 logs all statements
# and their durations.
#silent_mode = off # DO NOT USE without syslog or
# redirect_stderr
# (change requires restart)
# - What to Log -
#debug_print_parse = off
#debug_print_rewritten = off
#debug_print_plan = off
#debug_pretty_print = off
#log_connections = off
#log_disconnections = off
#log_duration = off
#log_line_prefix = '' # Special values:
# %u = user name
# %d = database name
# %r = remote host and port
# %h = remote host
# %p = PID
# %t = timestamp (no milliseconds)
# %m = timestamp with milliseconds
# %i = command tag
# %c = session id
# %l = session line number
# %s = session start timestamp
# %x = transaction id
# %q = stop here in non-session
# processes
# %% = '%'
# e.g. '<%u%%%d> '
#log_statement = 'none' # none, ddl, mod, all
#log_hostname = off
#---------------------------------------------------------------------------
# RUNTIME STATISTICS
#---------------------------------------------------------------------------
# - Query/Index Statistics Collector -
#stats_command_string = on
#update_process_title = on
#stats_start_collector = on # needed for block or row stats
# (change requires restart)
#stats_block_level = off
#stats_row_level = off
#stats_reset_on_server_start = off # (change requires restart)
# - Statistics Monitoring -
#log_parser_stats = off
#log_planner_stats = off
#log_executor_stats = off
#log_statement_stats = off
#---------------------------------------------------------------------------
# AUTOVACUUM PARAMETERS
#---------------------------------------------------------------------------
#autovacuum = off # enable autovacuum subprocess?
# 'on' requires stats_start_collector
# and stats_row_level to also be on
#autovacuum_naptime = 1min # time between autovacuum runs
#autovacuum_vacuum_threshold = 500 # min # of tuple updates before
# vacuum
#autovacuum_analyze_threshold = 250 # min # of tuple updates before
# analyze
#autovacuum_vacuum_scale_factor = 0.2 # fraction of rel size before
# vacuum
#autovacuum_analyze_scale_factor = 0.1 # fraction of rel size before
# analyze
#autovacuum_freeze_max_age = 200000000 # maximum XID age before forced vacuum
# (change requires restart)
#autovacuum_vacuum_cost_delay = -1 # default vacuum cost delay for
# autovacuum, -1 means use
# vacuum_cost_delay
#autovacuum_vacuum_cost_limit = -1 # default vacuum cost limit for
# autovacuum, -1 means use
# vacuum_cost_limit
#---------------------------------------------------------------------------
# CLIENT CONNECTION DEFAULTS
#---------------------------------------------------------------------------
# - Statement Behavior -
#search_path = '"$user",public' # schema names
#default_tablespace = '' # a tablespace name, '' uses
# the default
#check_function_bodies = on
#default_transaction_isolation = 'read committed'
#default_transaction_read_only = off
#statement_timeout = 0 # 0 is disabled
#vacuum_freeze_min_age = 100000000
# - Locale and Formatting -
datestyle = 'iso, mdy'
#timezone = unknown # actually, defaults to TZ
# environment setting
#timezone_abbreviations = 'Default' # select the set of available timezone
# abbreviations. Currently, there are
# Default
# Australia
# India
# However you can also create your own
# file in share/timezonesets/.
#extra_float_digits = 0 # min -15, max 2
#client_encoding = sql_ascii # actually, defaults to database
# encoding
# These settings are initialized by initdb -- they might be changed
lc_messages = 'en_US' # locale for system error message
# strings
lc_monetary = 'en_US' # locale for monetary formatting
lc_numeric = 'en_US' # locale for number formatting
lc_time = 'en_US' # locale for time formatting
# - Other Defaults -
#explain_pretty_print = on
#dynamic_library_path = '$libdir'
#local_preload_libraries = ''
#---------------------------------------------------------------------------
# LOCK MANAGEMENT
#---------------------------------------------------------------------------
#deadlock_timeout = 1s
#max_locks_per_transaction = 64 # min 10
# (change requires restart)
# Note: each lock table slot uses ~270 bytes of shared memory, and there are
# max_locks_per_transaction * (max_connections + max_prepared_transactions)
# lock table slots.
#---------------------------------------------------------------------------
# VERSION/PLATFORM COMPATIBILITY
#---------------------------------------------------------------------------
# - Previous Postgres Versions -
#add_missing_from = off
#array_nulls = on
#backslash_quote = safe_encoding # on, off, or safe_encoding
#default_with_oids = off
#escape_string_warning = on
#standard_conforming_strings = off
#regex_flavor = advanced # advanced, extended, or basic
#sql_inheritance = on
# - Other Platforms & Clients -
#transform_null_equals = off
#---------------------------------------------------------------------------
# CUSTOMIZED OPTIONS
#---------------------------------------------------------------------------
#custom_variable_classes = '' # list of custom variable class names
Any suggestions to improve things?
Shawn
>>> On Mon, Sep 3, 2007 at 11:15 AM, in message <20070903091558.0780b963@boffin.xmtservices.net>, Shawn <postgres@xmtservices.net> wrote: > On Sun, 02 Sep 2007 10:49:09 -0500 "Kevin Grittner" > <Kevin.Grittner@wicourts.gov> wrote: > >> >>> On Sat, Sep 1, 2007 at 12:29 PM, in message >> <20070901102947.0c0a50a3@boffin.xmtservices.net>, Shawn >> <postgres@xmtservices.net> wrote: >> > update shawns_data set alias = null; >> > Even after VACUUM this simple line takes 35 sec to complete. >> >> Would any rows already have a null alias when you run this? >> If so, try adding 'where alias is not null' to the query. > > This one initially added about 10sec to the run but I added a HASH > index on the alias field and its now about 5 sec average runtime, a net > improvement. Testing for null on 15,700 rows took five seconds more than the time saved from not updating some portion of the rows????? I've never seen anything remotely like that. Did you ever capture the output of VACUUM VERBOSE against this table (as Tom requested)? What happens if you run CLUSTER against this table before running one of these updates? (Be sure to do that VACUUM VERBOSE first, to see what the "old" state of the table was, and run it again after.) What is the row count from the second update of the table in your script? (An overly loose join there could bloat the table.) -Kevin
>>> On Mon, Sep 3, 2007 at 11:57 AM, in message <20070903095749.5045211b@boffin.xmtservices.net>, Shawn <postgres@xmtservices.net> wrote: > Also it runs a lot faster by itself Given the context of the run, there is a possibility that a checkpoint tends to fall at this point in the script because you're filling your WAL files. There is a known issue (which people have been working on fixing in 8.3) which causes the checkpoint to push a lot of pages to the disk and then wait on physical writes. If the VACUUM ANALYZE doesn't turn up anything useful, an interesting experiment would be to run your script with these modifications to your postgresql.conf file: bgwriter_lru_percent = 20.0 # 0-100% of LRU buffers scanned/round bgwriter_lru_maxpages = 200 # 0-1000 buffers max written/round bgwriter_all_percent = 10.0 # 0-100% of all buffers scanned/round bgwriter_all_maxpages = 600 # 0-1000 buffers max written/round Don't leave these in effect permanently without close attention to the overall impact. These settings have worked well for us, but are likely not to work well for everyone. -Kevin
On Mon, 03 Sep 2007 13:07:41 -0500 "Kevin Grittner" <Kevin.Grittner@wicourts.gov> wrote: > >>> On Mon, Sep 3, 2007 at 11:15 AM, in message > <20070903091558.0780b963@boffin.xmtservices.net>, Shawn > <postgres@xmtservices.net> wrote: > > On Sun, 02 Sep 2007 10:49:09 -0500 "Kevin Grittner" > > <Kevin.Grittner@wicourts.gov> wrote: > > > >> >>> On Sat, Sep 1, 2007 at 12:29 PM, in message > >> <20070901102947.0c0a50a3@boffin.xmtservices.net>, Shawn > >> <postgres@xmtservices.net> wrote: > >> > update shawns_data set alias = null; > >> > Even after VACUUM this simple line takes 35 sec to complete. > >> > >> Would any rows already have a null alias when you run this? > >> If so, try adding 'where alias is not null' to the query. > > > > This one initially added about 10sec to the run but I added a HASH > > index on the alias field and its now about 5 sec average runtime, a > > net improvement. > > Testing for null on 15,700 rows took five seconds more than the time > saved from not updating some portion of the rows????? I've never > seen anything remotely like that. > > Did you ever capture the output of VACUUM VERBOSE against this table > (as Tom requested)? > > What happens if you run CLUSTER against this table before running one > of these updates? (Be sure to do that VACUUM VERBOSE first, to see > what the "old" state of the table was, and run it again after.) > > What is the row count from the second update of the table in your > script? (An overly loose join there could bloat the table.) here is the vacuum results: vacuum verbose analyze shawns_data; INFO: vacuuming "public.shawns_data" INFO: scanned index "shawns_data_pkey" to remove 21444 row versions DETAIL: CPU 0.24s/0.12u sec elapsed 8.35 sec. INFO: scanned index "sd_l" to remove 21444 row versions DETAIL: CPU 0.32s/0.16u sec elapsed 6.11 sec. INFO: scanned index "sd_b" to remove 21444 row versions DETAIL: CPU 0.34s/0.13u sec elapsed 10.10 sec. INFO: scanned index "sd_s" to remove 21444 row versions DETAIL: CPU 0.36s/0.13u sec elapsed 7.16 sec. INFO: scanned index "sd_e" to remove 21444 row versions DETAIL: CPU 0.40s/0.17u sec elapsed 6.71 sec. INFO: scanned index "sd_alias_hash" to remove 21444 row versions DETAIL: CPU 0.00s/0.01u sec elapsed 0.01 sec. INFO: "shawns_data": removed 21444 row versions in 513 pages DETAIL: CPU 0.00s/0.00u sec elapsed 0.00 sec. INFO: index "shawns_data_pkey" now contains 15445 row versions in 35230 pages DETAIL: 21444 index row versions were removed. 19255 index pages have been deleted, 19255 are currently reusable. CPU 0.00s/0.00u sec elapsed 0.00 sec. INFO: index "sd_l" now contains 15445 row versions in 32569 pages DETAIL: 21444 index row versions were removed. 18059 index pages have been deleted, 18059 are currently reusable. CPU 0.00s/0.00u sec elapsed 0.00 sec. INFO: index "sd_b" now contains 15445 row versions in 34119 pages DETAIL: 21444 index row versions were removed. 30276 index pages have been deleted, 30219 are currently reusable. CPU 0.00s/0.00u sec elapsed 0.00 sec. INFO: index "sd_s" now contains 15445 row versions in 35700 pages DETAIL: 21444 index row versions were removed. 31284 index pages have been deleted, 31233 are currently reusable. CPU 0.00s/0.00u sec elapsed 0.00 sec. INFO: index "sd_e" now contains 15445 row versions in 42333 pages DETAIL: 21444 index row versions were removed. 28828 index pages have been deleted, 28820 are currently reusable. CPU 0.00s/0.00u sec elapsed 0.00 sec. INFO: index "sd_alias_hash" now contains 10722 row versions in 298 pages DETAIL: 10722 index row versions were removed. 0 index pages have been deleted, 0 are currently reusable. CPU 0.00s/0.00u sec elapsed 0.00 sec. INFO: "shawns_data": found 21444 removable, 15445 nonremovable row versions in 770 pages DETAIL: 0 dead row versions cannot be removed yet. There were 5825 unused item pointers. 543 pages contain useful free space. 0 pages are entirely empty. CPU 1.68s/0.77u sec elapsed 38.47 sec. INFO: analyzing "public.shawns_data" INFO: "shawns_data": scanned 770 of 770 pages, containing 15445 live rows and 0 dead rows; 3000 rows in sample, 15445 estimated total rows VACUUM Shawn
Shawn <postgres@xmtservices.net> writes:
> "Kevin Grittner" <Kevin.Grittner@wicourts.gov> wrote:
>> Did you ever capture the output of VACUUM VERBOSE against this table
> vacuum verbose analyze shawns_data;
> ...
> INFO: index "shawns_data_pkey" now contains 15445 row versions in
> 35230 pages
[ and comparably bloated sizes for other indexes ]
Ouch! The table itself doesn't look nearly as bad:
> INFO: "shawns_data": found 21444 removable, 15445 nonremovable row
> versions in 770 pages
but you've got a spectacularly bad case of index bloat. An index 50
times bigger than its table is Not Good. I think you'd find that
"REINDEX TABLE shawns_data" does wonders for the situation.
The next question is how it got to be that way... what is your
vacuuming policy for this database? Maybe you need to raise
max_fsm_pages?
regards, tom lane
>>> On Mon, Sep 3, 2007 at 6:53 PM, in message <20070903165334.0da769c1@boffin.xmtservices.net>, Shawn <postgres@xmtservices.net> wrote: > vacuum verbose analyze shawns_data; > INFO: vacuuming "public.shawns_data" > INFO: scanned index "shawns_data_pkey" to remove 21444 row versions > DETAIL: CPU 0.24s/0.12u sec elapsed 8.35 sec. > INFO: scanned index "sd_l" to remove 21444 row versions > DETAIL: CPU 0.32s/0.16u sec elapsed 6.11 sec. > INFO: scanned index "sd_b" to remove 21444 row versions > DETAIL: CPU 0.34s/0.13u sec elapsed 10.10 sec. > INFO: scanned index "sd_s" to remove 21444 row versions > DETAIL: CPU 0.36s/0.13u sec elapsed 7.16 sec. > INFO: scanned index "sd_e" to remove 21444 row versions > DETAIL: CPU 0.40s/0.17u sec elapsed 6.71 sec. > INFO: scanned index "sd_alias_hash" to remove 21444 row versions > DETAIL: CPU 0.00s/0.01u sec elapsed 0.01 sec. > INFO: "shawns_data": removed 21444 row versions in 513 pages > DETAIL: CPU 0.00s/0.00u sec elapsed 0.00 sec. > INFO: index "shawns_data_pkey" now contains 15445 row versions in > 35230 pages DETAIL: 21444 index row versions were removed. > 19255 index pages have been deleted, 19255 are currently reusable. > CPU 0.00s/0.00u sec elapsed 0.00 sec. > INFO: index "sd_l" now contains 15445 row versions in 32569 pages > DETAIL: 21444 index row versions were removed. > 18059 index pages have been deleted, 18059 are currently reusable. > CPU 0.00s/0.00u sec elapsed 0.00 sec. > INFO: index "sd_b" now contains 15445 row versions in 34119 pages > DETAIL: 21444 index row versions were removed. > 30276 index pages have been deleted, 30219 are currently reusable. > CPU 0.00s/0.00u sec elapsed 0.00 sec. > INFO: index "sd_s" now contains 15445 row versions in 35700 pages > DETAIL: 21444 index row versions were removed. > 31284 index pages have been deleted, 31233 are currently reusable. > CPU 0.00s/0.00u sec elapsed 0.00 sec. > INFO: index "sd_e" now contains 15445 row versions in 42333 pages > DETAIL: 21444 index row versions were removed. > 28828 index pages have been deleted, 28820 are currently reusable. > CPU 0.00s/0.00u sec elapsed 0.00 sec. > INFO: index "sd_alias_hash" now contains 10722 row versions in 298 > pages DETAIL: 10722 index row versions were removed. > 0 index pages have been deleted, 0 are currently reusable. > CPU 0.00s/0.00u sec elapsed 0.00 sec. > INFO: "shawns_data": found 21444 removable, 15445 nonremovable row > versions in 770 pages DETAIL: 0 dead row versions cannot be removed > yet. There were 5825 unused item pointers. > 543 pages contain useful free space. > 0 pages are entirely empty. > CPU 1.68s/0.77u sec elapsed 38.47 sec. Those indexes are killing you. Hopefully you realize that each of those indexes will have a new entry inserted whenever you update a row. If your indexes are that expensive to maintain, you want to go out of your way update rows only when something actually changes, which is not the case for your second update statement yet. I don't recall seeing the table definition yet. Could we see that, with the indexes? Also, have you tried that CLUSTER yet? Syntax: CLUSTER shawns_data_pkey ON shawns_data; ANALYZE shawns_data; (or VACUUM ANALYZE) This will clean up index bloat. -Kevin
On Mon, 03 Sep 2007 21:10:06 -0400 Tom Lane <tgl@sss.pgh.pa.us> wrote: > Shawn <postgres@xmtservices.net> writes: > > You weren't kidding, that really made a difference. its .5 sec now > > on the run. I think the vacuuming not running for a few weeks is > > what got me. I caught an edit that had stopped the vacuuming > > routine a while back. That must have been what caused the index > > bloat. > > Hmm, but no vacuuming at all would have allowed the table itself to > bloat too. Did you do a VACUUM FULL to recover after you noticed > the size problem? The trouble with VACUUM FULL is it compresses the > table but doesn't do a dang thing for indexes ... > > regards, tom lane > Thanks again to the list. I ran the reindex command that Tom suggested and things seem to be holding. Even the vacuum command is running faster. The whole script runs in about 10 seconds, far more acceptable. Thanks Guys! Shawn