Re: Identity projection

Hello, sorry for long absense,

# I had unexpected and urgent time-consuming tasks... :-(

I have had a bit more precise inspection by two aspects, and they
seemd showing that the difference should be the execution time of
ExecProject.

I'll be able to back fully next week with reviesed patch, and to
take some other pathes to review...

============
> Although I said as following, the gain seems a bit larger... I'll
> recheck the testing conditions...

I had inspected more precisely on two aspects maginifying the
effect of this patch by putting 300 columns into table.

First, explain analyze says the difference caused by this patch
is only in the actual time of Result node.

orig$ psql -c 'explain analyze select * from parenta'
QUERY PLAN
--------------------------------------------------------------------------
Result (cost=0.00..176667.00 rows=1000001 width=1202)
(actual time=0.013.. *2406.792* rows=1000000 loops=1)
-> Append (cost=0.00..176667.00 rows=1000001 width=1202)
(actual time=0.011..412.749 rows=1000000 loops=1)
-> Seq Scan on parenta (cost=0.00..0.00 rows=1 width=1228)
(actual time=0.001..0.001 rows=0 loops=1)
-> Seq Scan on childa000 parenta
(cost=0.00..176667.00 rows=1000000 width=1202)
(actual time=0.009..334.633 rows=1000000 loops=1)
Total runtime: 2446.474 ms
(5 rows)

patched$ psql -c 'explain analyze select * from parenta'
QUERY PLAN
--------------------------------------------------------------------------
Result (cost=0.00..176667.00 rows=1000001 width=1202)
(actual time=0.011.. *507.239* rows=1000000 loops=1)
-> Append (cost=0.00..176667.00 rows=1000001 width=1202)
(actual time=0.011..419.420 rows=1000000 loops=1)
-> Seq Scan on parenta (cost=0.00..0.00 rows=1 width=1228)
(actual time=0.000..0.000 rows=0 loops=1)
-> Seq Scan on childa000 parenta
(cost=0.00..176667.00 rows=1000000 width=1202)
(actual time=0.010..335.721 rows=1000000 loops=1)
Total runtime: 545.879 ms
(5 rows)

Second, the results of configure --enable-profiling shows that
the exectime of ExecProject chages greately. This is consistent
with what explain showed.

orig:
> % cumulative self self total
> time seconds seconds calls s/call s/call name
> 60.29 1.26 1.26 1000005 0.00 0.00 slot_deform_tuple
!> 30.14 1.89 0.63 1000000 0.00 0.00 ExecProject
> 3.35 1.96 0.07 3000004 0.00 0.00 ExecProcNode
> 0.96 1.98 0.02 1000002 0.00 0.00 ExecScan
> 0.96 2.00 0.02 166379 0.00 0.00 TerminateBufferIO
> 0.48 2.01 0.01 3000004 0.00 0.00 InstrStartNode
> 0.48 2.02 0.01 3000004 0.00 0.00 InstrStopNode
!> 0.48 2.03 0.01 1000001 0.00 0.00 ExecResult
> 0.48 2.04 0.01 830718 0.00 0.00 LWLockAcquire
> 0.48 2.05 0.01 506834 0.00 0.00 hash_search_with_hash_value
> 0.48 2.06 0.01 341656 0.00 0.00 LockBuffer
> 0.48 2.07 0.01 168383 0.00 0.00 ReadBuffer_common
> 0.48 2.08 0.01 4 0.00 0.00 InstrEndLoop
> 0.48 2.09 0.01 ExecCleanTargetListLength
> 0.00 2.09 0.00 2000005 0.00 0.00 MemoryContextReset

patched:
> % cumulative self self total
> time seconds seconds calls ms/call ms/call name
> 23.08 0.03 0.03 3000004 0.00 0.00 ExecProcNode
> 15.38 0.05 0.02 1000002 0.00 0.00 heapgettup_pagemode
> 15.38 0.07 0.02 830718 0.00 0.00 LWLockAcquire
> 7.69 0.08 0.01 2000005 0.00 0.00 MemoryContextReset
> 7.69 0.09 0.01 1000002 0.00 0.00 ExecScan
> 7.69 0.10 0.01 1000000 0.00 0.00 ExecStoreTuple
> 7.69 0.11 0.01 841135 0.00 0.00 LWLockRelease
> 7.69 0.12 0.01 168383 0.00 0.00 ReadBuffer_common
> 7.69 0.13 0.01 168383 0.00 0.00 UnpinBuffer
> 0.00 0.13 0.00 3000004 0.00 0.00 InstrStartNode
...
!> 0.00 0.13 0.00 1000001 0.00 0.00 ExecResult
!> 0.00 0.13 0.00 1000000 0.00 0.00 ExecProject

regards,

--
Kyotaro Horiguchi
NTT Open Source Software Center