On Thu, May 27, 2021 at 9:53 AM Bharath Rupireddy <bharath.rupireddyforpostg...@gmail.com> wrote: > > One idea to find this out could be that we have three counters for > > each worker which counts the number of times each worker extended the > > relation in bulk, the number of times each worker extended the > > relation by one block, the number of times each worker gets the page > > from FSM. It might be possible that with this we will be able to > > figure out why there is a difference between your and Hou-San's > > results. > > Yeah, that helps. And also, the time spent in > LockRelationForExtension, ConditionalLockRelationForExtension, > GetPageWithFreeSpace and RelationAddExtraBlocks too can give some > insight. > > My plan is to have a patch with above info added in (which I will > share it here so that others can test and see the results too) and run > the "case 4" where there's a regression seen on my system.
I captured below information with the attached patch 0001-test-times-and-block-counts.patch applied on top of CTAS v23 patch set. Testing details are attached in the file named "test". Total time spent in LockRelationForExtension Total time spent in GetPageWithFreeSpace Total time spent in RelationAddExtraBlocks Total number of times extended the relation in bulk Total number of times extended the relation by one block Total number of blocks added in bulk extension Total number of times getting the page from FSM Here is a summary of what I observed: 1) The execution time with 2 workers, without TABLE_INSERT_SKIP_FSM (140 sec) is more than with 0 workers (112 sec) 2) The execution time with 2 workers, with TABLE_INSERT_SKIP_FSM (225 sec) is more than with 2 workers, without TABLE_INSERT_SKIP_FSM (140 sec) 3) Majority of the time is going into waiting for relation extension lock in LockRelationForExtension. With 2 workers, without TABLE_INSERT_SKIP_FSM, out of total execution time 140 sec, the time spent in LockRelationForExtension is ~40 sec and the time spent in RelationAddExtraBlocks is ~20 sec. So, ~60 sec are being spent in these two functions. With 2 workers, with TABLE_INSERT_SKIP_FSM, out of total execution time 225 sec, the time spent in LockRelationForExtension is ~135 sec and the time spent in RelationAddExtraBlocks is 0 sec (because we skip FSM, no bulk extend logic applies). So, most of the time is being spent in LockRelationForExtension. I'm still not sure why the execution time with 0 workers (or serial execution or no parallelism involved) on my testing system is 112 sec compared to 58 sec on Hou-San's system for the same use case. Maybe the testing system I'm using is not of the latest configuration compared to others. Having said that, I request others to try and see if the same observations (as above) are made on their testing systems for the same use case. If others don't see regression (with just 2 workers) or they observe not much difference with and without TABLE_INSERT_SKIP_FSM. I'm open to changing the parallel inserts in CTAS code to use TABLE_INSERT_SKIP_FSM. In any case, if the observation is that there's a good amount of time being spent in LockRelationForExtension, I'm not sure (at this point) whether we can do something here or just live with it. With Regards, Bharath Rupireddy. EnterpriseDB: http://www.enterprisedb.com
From 105495d5aa6b25f61c812dd5cb9ff692abe38373 Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <bharath.rupireddy@enterprisedb.com>
Date: Thu, 27 May 2021 13:37:32 +0530
Subject: [PATCH] test times and block counts
---
src/backend/access/heap/hio.c | 21 ++++++++++++
src/backend/commands/createas.c | 41 +++++++++++++++++++++++
src/backend/storage/freespace/freespace.c | 22 +++++++++++-
src/backend/storage/lmgr/lmgr.c | 13 +++++++
src/include/commands/createas.h | 17 ++++++++++
5 files changed, 113 insertions(+), 1 deletion(-)
diff --git a/src/backend/access/heap/hio.c b/src/backend/access/heap/hio.c
index d34edb4190..d737c2d763 100644
--- a/src/backend/access/heap/hio.c
+++ b/src/backend/access/heap/hio.c
@@ -19,6 +19,8 @@
#include "access/hio.h"
#include "access/htup_details.h"
#include "access/visibilitymap.h"
+#include "commands/createas.h"
+#include "portability/instr_time.h"
#include "storage/bufmgr.h"
#include "storage/freespace.h"
#include "storage/lmgr.h"
@@ -198,12 +200,17 @@ RelationAddExtraBlocks(Relation relation, BulkInsertState bistate)
firstBlock = InvalidBlockNumber;
int extraBlocks;
int lockWaiters;
+ instr_time start;
+ instr_time end;
/* Use the length of the lock wait queue to judge how much to extend. */
lockWaiters = RelationExtensionLockWaiterCount(relation);
if (lockWaiters <= 0)
return;
+ if (is_ctas)
+ INSTR_TIME_SET_CURRENT(start);
+
/*
* It might seem like multiplying the number of lock waiters by as much as
* 20 is too aggressive, but benchmarking revealed that smaller numbers
@@ -212,6 +219,9 @@ RelationAddExtraBlocks(Relation relation, BulkInsertState bistate)
*/
extraBlocks = Min(512, lockWaiters * 20);
+ if (is_ctas)
+ bulk_rel_extension_blocks_count += extraBlocks;
+
do
{
Buffer buffer;
@@ -267,6 +277,14 @@ RelationAddExtraBlocks(Relation relation, BulkInsertState bistate)
* just inserted.
*/
FreeSpaceMapVacuumRange(relation, firstBlock, blockNum + 1);
+
+ if (is_ctas)
+ {
+ INSTR_TIME_SET_CURRENT(end);
+ INSTR_TIME_SUBTRACT(end, start);
+ rel_add_extra_blocks_time += INSTR_TIME_GET_MICROSEC(end);
+ bulk_rel_extension_count++;
+ }
}
/*
@@ -630,6 +648,9 @@ loop:
*/
page = BufferGetPage(buffer);
+ if (is_ctas)
+ single_block_rel_extension_count++;
+
if (!PageIsNew(page))
elog(ERROR, "page %u of relation \"%s\" should be empty but is not",
BufferGetBlockNumber(buffer),
diff --git a/src/backend/commands/createas.c b/src/backend/commands/createas.c
index 53ca3010c6..df23a72335 100644
--- a/src/backend/commands/createas.c
+++ b/src/backend/commands/createas.c
@@ -62,6 +62,14 @@ static bool intorel_receive(TupleTableSlot *slot, DestReceiver *self);
static void intorel_shutdown(DestReceiver *self);
static void intorel_destroy(DestReceiver *self);
+bool is_ctas = false;
+uint64 lock_rel_extension_time = 0;
+uint64 get_page_from_fsm_time = 0;
+uint64 rel_add_extra_blocks_time = 0;
+uint64 bulk_rel_extension_count = 0;
+uint64 single_block_rel_extension_count = 0;
+uint64 fsm_hit_count = 0;
+uint64 bulk_rel_extension_blocks_count = 0;
/*
* create_ctas_internal
@@ -482,6 +490,14 @@ intorel_startup(DestReceiver *self, int operation, TupleDesc typeinfo)
ListCell *lc;
int attnum;
+ lock_rel_extension_time = 0;
+ get_page_from_fsm_time = 0;
+ rel_add_extra_blocks_time = 0;
+ bulk_rel_extension_count = 0;
+ single_block_rel_extension_count = 0;
+ fsm_hit_count = 0;
+ bulk_rel_extension_blocks_count = 0;
+
/*
* All the necessary work such as table creation, sanity checks etc. would
* have been done by the leader. So, parallel workers just need to open the
@@ -652,6 +668,7 @@ intorel_receive(TupleTableSlot *slot, DestReceiver *self)
/* Nothing to insert if WITH NO DATA is specified. */
if (!myState->into->skipData)
{
+ is_ctas = true;
/*
* Note that the input slot might not be of the type of the target
* relation. That's supported by table_tuple_insert(), but slightly
@@ -665,6 +682,7 @@ intorel_receive(TupleTableSlot *slot, DestReceiver *self)
myState->output_cid,
myState->ti_options,
myState->bistate);
+ is_ctas = false;
}
/* We know this is a newly created relation, so there are no indexes */
@@ -690,6 +708,29 @@ intorel_shutdown(DestReceiver *self)
/* close rel, but keep lock until commit */
table_close(myState->rel, NoLock);
myState->rel = NULL;
+
+ ereport(LOG, (errmsg("Total time spent in LockRelationForExtension is %f msec",
+ (((double) lock_rel_extension_time) / 1000.0)), errhidestmt(true)));
+ ereport(LOG, (errmsg("Total time spent in GetPageWithFreeSpace is %f msec",
+ (((double) get_page_from_fsm_time) / 1000.0)), errhidestmt(true)));
+ ereport(LOG, (errmsg("Total time spent in RelationAddExtraBlocks is %f msec",
+ (((double) rel_add_extra_blocks_time) / 1000.0)), errhidestmt(true)));
+ ereport(LOG, (errmsg("Total number of times extended the relation in bulk is %lu",
+ bulk_rel_extension_count), errhidestmt(true)));
+ ereport(LOG, (errmsg("Total number of blocks added in bulk extension is %lu",
+ bulk_rel_extension_blocks_count), errhidestmt(true)));
+ ereport(LOG, (errmsg("Total number of times extended the relation by one block is %lu",
+ single_block_rel_extension_count), errhidestmt(true)));
+ ereport(LOG, (errmsg("Total number of times getting the page from FSM is %lu",
+ fsm_hit_count), errhidestmt(true)));
+
+ lock_rel_extension_time = 0;
+ get_page_from_fsm_time = 0;
+ rel_add_extra_blocks_time = 0;
+ bulk_rel_extension_count = 0;
+ single_block_rel_extension_count = 0;
+ fsm_hit_count = 0;
+ bulk_rel_extension_blocks_count = 0;
}
/*
diff --git a/src/backend/storage/freespace/freespace.c b/src/backend/storage/freespace/freespace.c
index 8c12dda238..518170a790 100644
--- a/src/backend/storage/freespace/freespace.c
+++ b/src/backend/storage/freespace/freespace.c
@@ -25,7 +25,9 @@
#include "access/htup_details.h"
#include "access/xlogutils.h"
+#include "commands/createas.h"
#include "miscadmin.h"
+#include "portability/instr_time.h"
#include "storage/freespace.h"
#include "storage/fsm_internals.h"
#include "storage/lmgr.h"
@@ -132,8 +134,26 @@ BlockNumber
GetPageWithFreeSpace(Relation rel, Size spaceNeeded)
{
uint8 min_cat = fsm_space_needed_to_cat(spaceNeeded);
+ BlockNumber blk_no;
+ instr_time start;
+ instr_time end;
- return fsm_search(rel, min_cat);
+ if (is_ctas)
+ INSTR_TIME_SET_CURRENT(start);
+
+ blk_no = fsm_search(rel, min_cat);
+
+ if (is_ctas)
+ {
+ INSTR_TIME_SET_CURRENT(end);
+ INSTR_TIME_SUBTRACT(end, start);
+ get_page_from_fsm_time += INSTR_TIME_GET_MICROSEC(end);
+
+ if (blk_no != InvalidBlockNumber)
+ fsm_hit_count++;
+ }
+
+ return blk_no;
}
/*
diff --git a/src/backend/storage/lmgr/lmgr.c b/src/backend/storage/lmgr/lmgr.c
index cdf2266d6d..bed87898ae 100644
--- a/src/backend/storage/lmgr/lmgr.c
+++ b/src/backend/storage/lmgr/lmgr.c
@@ -19,6 +19,7 @@
#include "access/transam.h"
#include "access/xact.h"
#include "catalog/catalog.h"
+#include "commands/createas.h"
#include "commands/progress.h"
#include "miscadmin.h"
#include "pgstat.h"
@@ -403,12 +404,24 @@ void
LockRelationForExtension(Relation relation, LOCKMODE lockmode)
{
LOCKTAG tag;
+ instr_time start;
+ instr_time end;
+
+ if (is_ctas)
+ INSTR_TIME_SET_CURRENT(start);
SET_LOCKTAG_RELATION_EXTEND(tag,
relation->rd_lockInfo.lockRelId.dbId,
relation->rd_lockInfo.lockRelId.relId);
(void) LockAcquire(&tag, lockmode, false, false);
+
+ if (is_ctas)
+ {
+ INSTR_TIME_SET_CURRENT(end);
+ INSTR_TIME_SUBTRACT(end, start);
+ lock_rel_extension_time += INSTR_TIME_GET_MICROSEC(end);
+ }
}
/*
diff --git a/src/include/commands/createas.h b/src/include/commands/createas.h
index 74022aab41..6f998c6146 100644
--- a/src/include/commands/createas.h
+++ b/src/include/commands/createas.h
@@ -21,6 +21,23 @@
#include "tcop/dest.h"
#include "utils/queryenvironment.h"
+extern bool is_ctas;
+/* time spent in LockRelationForExtension */
+extern uint64 lock_rel_extension_time;
+/* time spent in GetPageWithFreeSpace */
+extern uint64 get_page_from_fsm_time;
+ /* time spent in RelationAddExtraBlocks */
+extern uint64 rel_add_extra_blocks_time;
+/* number of times each worker extended the relation in bulk */
+extern uint64 bulk_rel_extension_count;
+/* number of times each worker extended the relation by one block */
+extern uint64 single_block_rel_extension_count;
+/* number of times each worker gets the page from FSM */
+extern uint64 fsm_hit_count;
+/* number of blocks added in bulk extension */
+extern uint64 bulk_rel_extension_blocks_count;
+
+
typedef struct
{
DestReceiver pub; /* publicly-known function pointers */
--
2.25.1
test
Description: Binary data
