Remove command slow in 13.3


#1

Hello,

Just updated to 13.3 and noticed the remove command (e.g. remove(tb36h) ) is taking around ~10-15 seconds for an array with this format:

iquery -r /dev/null -avq "scan(tb36h)"

Any ideas why this would be happening? Started the project just after the update so didn’t have a chance to test it on another version.

Thanks,

Nick


#2

I’m confused …

Your subject seems to indicate that remove(…) is slow.

But your repro used scan(…).

In your iquery example, you’re scanning the entire tb36h array, and the client is writing the result to /dev/null. Depending on the size of the query–and your array seems to hold about 1,000,000 values, you’re going to get several Meg (say, 8 Meg) back to the client, the client’s going to format it into something readable, and then you’re going to push it down /dev/null.

A few seconds to return and format 8Meg is not terribly unreasonable, is it?

Try:

/usr/bin/time -f "Elapsed Time: %E" iquery -r /dev/null -avq "count(tb36h)"

#3

Sorry confusing post on my part. I added the scan of an array to give you an idea of the size of an array that I am trying to remove.

The gist of my problem is that arrays like the one I posted are taking about 15 seconds to remove and under a second to load.

The majority of time In my current loading/redimensioning process is spent removing temporary variables. Does this sound right?

Nick


#4

Hmmmm …

Yours is the second user we’ve had who has reported slow action with DDL (remove, create array).

  1. Would you be so kind as to run the postgres ‘ANALYZE’ command on the database? I suspect, if you’re in the habit of creating and removing a lot of arrays that the postgres optimizer might be getting confused.

postgresql.org/docs/8.4/stat … alyze.html

  1. We might need to create a couple of indices on the postgres catalogs to improve things when there are lots and lots of create / remove operations.

So - please try #1. I’ll create a ticket and get someone to look at #2.


#5

Sure thing, here is what I’m getting:

smap2=# ANALYZE VERBOSE;
INFO:  analyzing "pg_catalog.pg_type"
INFO:  "pg_type": scanned 10 of 10 pages, containing 338 live rows and 0 dead rows; 338 rows in sample, 338 estimated total rows
INFO:  analyzing "pg_catalog.pg_attribute"
INFO:  "pg_attribute": scanned 55 of 55 pages, containing 2427 live rows and 0 dead rows; 2427 rows in sample, 2427 estimated total rows
INFO:  analyzing "pg_catalog.pg_authid"
INFO:  "pg_authid": scanned 1 of 1 pages, containing 4 live rows and 1 dead rows; 4 rows in sample, 4 estimated total rows
INFO:  analyzing "pg_catalog.pg_proc"
INFO:  "pg_proc": scanned 57 of 57 pages, containing 2346 live rows and 13 dead rows; 2346 rows in sample, 2346 estimated total rows
INFO:  analyzing "pg_catalog.pg_class"
INFO:  "pg_class": scanned 11 of 11 pages, containing 321 live rows and 100 dead rows; 321 rows in sample, 321 estimated total rows
INFO:  analyzing "pg_catalog.pg_database"
INFO:  "pg_database": scanned 1 of 1 pages, containing 11 live rows and 5 dead rows; 11 rows in sample, 11 estimated total rows
INFO:  analyzing "pg_catalog.pg_user_mapping"
INFO:  "pg_user_mapping": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
INFO:  analyzing "pg_catalog.pg_constraint"
INFO:  "pg_constraint": scanned 2 of 2 pages, containing 21 live rows and 19 dead rows; 21 rows in sample, 21 estimated total rows
INFO:  analyzing "pg_catalog.pg_inherits"
INFO:  "pg_inherits": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
INFO:  analyzing "pg_catalog.pg_index"
INFO:  "pg_index": scanned 4 of 4 pages, containing 129 live rows and 0 dead rows; 129 rows in sample, 129 estimated total rows
INFO:  analyzing "pg_catalog.pg_operator"
INFO:  "pg_operator": scanned 13 of 13 pages, containing 706 live rows and 0 dead rows; 706 rows in sample, 706 estimated total rows
INFO:  analyzing "pg_catalog.pg_opfamily"
INFO:  "pg_opfamily": scanned 1 of 1 pages, containing 70 live rows and 0 dead rows; 70 rows in sample, 70 estimated total rows
INFO:  analyzing "pg_catalog.pg_opclass"
INFO:  "pg_opclass": scanned 2 of 2 pages, containing 113 live rows and 0 dead rows; 113 rows in sample, 113 estimated total rows
INFO:  analyzing "pg_catalog.pg_amop"
INFO:  "pg_amop": scanned 3 of 3 pages, containing 359 live rows and 0 dead rows; 359 rows in sample, 359 estimated total rows
INFO:  analyzing "pg_catalog.pg_amproc"
INFO:  "pg_amproc": scanned 2 of 2 pages, containing 252 live rows and 0 dead rows; 252 rows in sample, 252 estimated total rows
INFO:  analyzing "pg_catalog.pg_language"
INFO:  "pg_language": scanned 1 of 1 pages, containing 4 live rows and 2 dead rows; 4 rows in sample, 4 estimated total rows
INFO:  analyzing "pg_catalog.pg_largeobject_metadata"
INFO:  "pg_largeobject_metadata": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
INFO:  analyzing "pg_catalog.pg_aggregate"
INFO:  "pg_aggregate": scanned 1 of 1 pages, containing 119 live rows and 0 dead rows; 119 rows in sample, 119 estimated total rows
INFO:  analyzing "pg_catalog.pg_rewrite"
INFO:  "pg_rewrite": scanned 11 of 11 pages, containing 101 live rows and 0 dead rows; 101 rows in sample, 101 estimated total rows
INFO:  analyzing "pg_catalog.pg_trigger"
INFO:  "pg_trigger": scanned 2 of 2 pages, containing 26 live rows and 26 dead rows; 26 rows in sample, 26 estimated total rows
INFO:  analyzing "pg_catalog.pg_description"
INFO:  "pg_description": scanned 29 of 29 pages, containing 3276 live rows and 0 dead rows; 3276 rows in sample, 3276 estimated total rows
INFO:  analyzing "pg_catalog.pg_cast"
INFO:  "pg_cast": scanned 2 of 2 pages, containing 196 live rows and 0 dead rows; 196 rows in sample, 196 estimated total rows
INFO:  analyzing "pg_catalog.pg_enum"
INFO:  "pg_enum": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
INFO:  analyzing "pg_catalog.pg_namespace"
INFO:  "pg_namespace": scanned 1 of 1 pages, containing 6 live rows and 0 dead rows; 6 rows in sample, 6 estimated total rows
INFO:  analyzing "pg_catalog.pg_conversion"
INFO:  "pg_conversion": scanned 3 of 3 pages, containing 132 live rows and 0 dead rows; 132 rows in sample, 132 estimated total rows
INFO:  analyzing "pg_catalog.pg_depend"
INFO:  "pg_depend": scanned 49 of 49 pages, containing 6004 live rows and 641 dead rows; 6004 rows in sample, 6004 estimated total rows
INFO:  analyzing "pg_catalog.pg_largeobject"
INFO:  "pg_largeobject": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
INFO:  analyzing "pg_catalog.pg_tablespace"
INFO:  "pg_tablespace": scanned 1 of 1 pages, containing 2 live rows and 0 dead rows; 2 rows in sample, 2 estimated total rows
INFO:  analyzing "pg_catalog.pg_pltemplate"
INFO:  "pg_pltemplate": scanned 1 of 1 pages, containing 8 live rows and 0 dead rows; 8 rows in sample, 8 estimated total rows
INFO:  analyzing "pg_catalog.pg_auth_members"
INFO:  "pg_auth_members": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
INFO:  analyzing "pg_catalog.pg_shdepend"
INFO:  "pg_shdepend": scanned 1 of 1 pages, containing 39 live rows and 32 dead rows; 39 rows in sample, 39 estimated total rows
INFO:  analyzing "pg_catalog.pg_shdescription"
INFO:  "pg_shdescription": scanned 1 of 1 pages, containing 3 live rows and 0 dead rows; 3 rows in sample, 3 estimated total rows
INFO:  analyzing "pg_catalog.pg_ts_config"
INFO:  "pg_ts_config": scanned 1 of 1 pages, containing 16 live rows and 0 dead rows; 16 rows in sample, 16 estimated total rows
INFO:  analyzing "pg_catalog.pg_ts_config_map"
INFO:  "pg_ts_config_map": scanned 2 of 2 pages, containing 304 live rows and 0 dead rows; 304 rows in sample, 304 estimated total rows
INFO:  analyzing "pg_catalog.pg_ts_dict"
INFO:  "pg_ts_dict": scanned 1 of 1 pages, containing 16 live rows and 0 dead rows; 16 rows in sample, 16 estimated total rows
INFO:  analyzing "pg_catalog.pg_ts_parser"
INFO:  "pg_ts_parser": scanned 1 of 1 pages, containing 1 live rows and 0 dead rows; 1 rows in sample, 1 estimated total rows
INFO:  analyzing "pg_catalog.pg_ts_template"
INFO:  "pg_ts_template": scanned 1 of 1 pages, containing 5 live rows and 0 dead rows; 5 rows in sample, 5 estimated total rows
INFO:  analyzing "pg_catalog.pg_extension"
INFO:  "pg_extension": scanned 1 of 1 pages, containing 1 live rows and 0 dead rows; 1 rows in sample, 1 estimated total rows
INFO:  analyzing "pg_catalog.pg_foreign_data_wrapper"
INFO:  "pg_foreign_data_wrapper": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
INFO:  analyzing "pg_catalog.pg_foreign_server"
INFO:  "pg_foreign_server": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
INFO:  analyzing "pg_catalog.pg_foreign_table"
INFO:  "pg_foreign_table": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
INFO:  analyzing "pg_catalog.pg_default_acl"
INFO:  "pg_default_acl": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
INFO:  analyzing "pg_catalog.pg_seclabel"
INFO:  "pg_seclabel": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 estimated total rows
INFO:  analyzing "pg_catalog.pg_collation"
INFO:  "pg_collation": scanned 2 of 2 pages, containing 43 live rows and 0 dead rows; 43 rows in sample, 43 estimated total rows
INFO:  analyzing "information_schema.sql_implementation_info"
INFO:  "sql_implementation_info": scanned 1 of 1 pages, containing 12 live rows and 0 dead rows; 12 rows in sample, 12 estimated total rows
INFO:  analyzing "information_schema.sql_languages"
INFO:  "sql_languages": scanned 1 of 1 pages, containing 4 live rows and 0 dead rows; 4 rows in sample, 4 estimated total rows
INFO:  analyzing "information_schema.sql_packages"
INFO:  "sql_packages": scanned 1 of 1 pages, containing 10 live rows and 0 dead rows; 10 rows in sample, 10 estima
INFO:  analyzing "information_schema.sql_parts"
INFO:  "sql_parts": scanned 1 of 1 pages, containing 9 live rows and 0 dead rows; 9 rows in sample, 9 estimated to
INFO:  analyzing "information_schema.sql_sizing"
INFO:  "sql_sizing": scanned 1 of 1 pages, containing 23 live rows and 0 dead rows; 23 rows in sample, 23 estimate
INFO:  analyzing "information_schema.sql_sizing_profiles"
INFO:  "sql_sizing_profiles": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows; 0 rows in sample, 0 es
INFO:  analyzing "pg_catalog.pg_attrdef"
INFO:  "pg_attrdef": scanned 1 of 1 pages, containing 4 live rows and 16 dead rows; 4 rows in 
INFO:  analyzing "pg_catalog.pg_am"
INFO:  "pg_am": scanned 1 of 1 pages, containing 4 live rows and 0 dead rows; 4 row
INFO:  analyzing "pg_catalog.pg_db_role_setting"
INFO:  "pg_db_role_setting": scanned 1 of 1 pages, containing 1 live rows and 0 
INFO:  analyzing "information_schema.sql_features"
INFO:  "sql_features": scanned 7 of 7 pages, containing 650 live rows and 0 dead
INFO:  analyzing "public.cluster"
INFO:  "cluster": scanned 1 of 1 pages, containing 1 live rows and 0 dead rows; 
INFO:  analyzing "public.array_version"
INFO:  "array_version": scanned 2 of 2 pages, containing 128 live rows and 11 de
INFO:  analyzing "public.array_version_lock"
INFO:  "array_version_lock": scanned 1 of 1 pages, containing 0 live rows and 43
INFO:  analyzing "public.instance"
INFO:  "instance": scanned 1 of 1 pages, containing 1 live rows and 15 dead rows
INFO:  analyzing "public.array_partition"
INFO:  "array_partition": scanned 0 of 0 pages, containing 0 live rows and 0 dea
INFO:  analyzing "public.array"
INFO:  "array": scanned 4 of 4 pages, containing 224 live rows and 52 dead rows;
INFO:  analyzing "public.array_dimension"
INFO:  "array_dimension": scanned 8 of 8 pages, containing 385 live rows and 67 
INFO:  analyzing "public.array_attribute"
INFO:  "array_attribute": scanned 46 of 46 pages, containing 3151 live rows and 
INFO:  analyzing "public.libraries"
INFO:  "libraries": scanned 0 of 0 pages, containing 0 live rows and 0 dead rows

Also, I just realized that my Scidb install is using postgres 9.1. Must have used wrong port in the init file. Could this have something to do with it?

Thanks a ton for your help.

Nick


#6

We haven’t tested against Postgres 9.1, so that might be a problem. There might be something going wrong deep in the connectivity layer with 9.1 but we wouldn’t be aware of that.

I’m running this at the moment in an effort to understand whether things slow down with lots of create / remove commands. I’ll stretch this to see what happens when we create lots of array versions (repeated store ( build ( … ), array ) AFLs on te same array.)

#!/bin/sh
#
#
exec_afl_query () {
    echo "Query: ${1}"
    /usr/bin/time -f "Elapsed Time: %E" iquery -o dcsv ${2} -aq "${1}"
};
#
exec_aql_query () {
    echo "Query: ${1}"
    /usr/bin/time -f "Elapsed Time: %E" iquery -o dcsv ${2} -q "${1}"
};
#
#------------------------------------------------------------------------------
#
echo "" > /tmp/O 
#
for i in $(seq 1 3000); do
  ARRAY_NAME=$(echo "ARRAY_${i}");

  CMD_CREATE="
CREATE ARRAY ${ARRAY_NAME} 
< attr6 : int64, attr5 : int64, attr4 : int64, 
  attr3 : int64, attr2 : string, attr1 : double > 
[ I=0:99, 100, 0 ]
"

  CMD_POPULATE="
store ( 
  apply ( 
    build ( < attr6 : int64 > [ I=0:99,100,0 ], I),
    attr6, random()%10000, attr5, random()%10000,
    attr4, random()%10000, attr3, random()%10000,
    attr2, 'Foo_' + string(random()%10000),
    attr1, double((random()%10000) / 100.0)
  ),
  ${ARRAY_NAME}
)
"

  CMD_REMOVE="
remove ( ${ARRAY_NAME} )
"

  iquery -aq "${CMD_CREATE};" > /dev/null 2>&1
  iquery -aq "${CMD_POPULATE};" > /dev/null  2>&1
  exec_afl_query "${CMD_REMOVE};" >> /tmp/O 2>&1 

done

cat /tmp/O | grep "Elapsed" | sed 's/ /   /g' | gawk '{ print $3 }' | gawk -F: '{ print $2 }' 

#
#
# -- END -- 

Looking at the results of your ANALYZE operation? There really isn’t very much in those array_* tables. The queries we run to exercise the catalogs aren’t complex.

I’m leaning to the conclusion that using Postgres 9.1 is the source of the problem. Will investigate more.

Thanks for your cooperation & help with this.


#7

OK, I will backup and reinit using postgres 8.4. I will let you know if this solves things.


#8

Just to follow-up, your suggestion worked. I moved SciDB to its own instance of postgres 8.4 and haven’t had any further problems. Previously it was running on 9.1. (I was also using the 8.4 instance for other projects, other possible source of issues ?)

Anyway hopefully this is useful and thanks again for the help!