php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Request #62498 pdo_pgsql inefficient when getColumnMeta() is used
Submitted: 2012-07-07 09:47 UTC Modified: 2016-04-05 13:43 UTC
Votes:6
Avg. Score:4.3 ± 0.7
Reproduced:5 of 5 (100.0%)
Same Version:0 (0.0%)
Same OS:0 (0.0%)
From: c dot kworr at gmail dot com Assigned: ab
Status: Closed Package: PostgreSQL related
PHP Version: 5.3.14 OS: FreeBSD 9.0
Private report: No CVE-ID:
 [2012-07-07 09:47 UTC] c dot kworr at gmail dot com
Description:
------------
The function pgsql_stmt_get_column_meta (backend for getColumnMeta() doesn't 
cache or bulk request required data.

Nowadays many frameworks (I see this in Yii and Cake) abuse getColumnMeta() 
despite it's been marked experimental. In postgresql logs this looks like:

Jul  7 12:38:21 beeb postgres[21517]: [1150-1] localhost LOG:  duration: 3.961 
ms  parse pdo_stmt_00000044: SELECT ...
Jul  7 12:38:21 beeb postgres[21517]: [1150-2] ...
Jul  7 12:38:21 beeb postgres[21517]: [1150-3] ...
Jul  7 12:38:21 beeb postgres[21517]: [1150-4] ...
Jul  7 12:38:21 beeb postgres[21517]: [1150-5] ...;
Jul  7 12:38:21 beeb postgres[21517]: [1151-1] localhost LOG:  duration: 0.174 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=20
Jul  7 12:38:21 beeb postgres[21517]: [1152-1] localhost LOG:  duration: 0.124 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=1043
Jul  7 12:38:21 beeb postgres[21517]: [1153-1] localhost LOG:  duration: 0.125 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=1043
Jul  7 12:38:21 beeb postgres[21517]: [1154-1] localhost LOG:  duration: 0.119 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=1043
Jul  7 12:38:21 beeb postgres[21517]: [1155-1] localhost LOG:  duration: 0.119 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=1043
Jul  7 12:38:21 beeb postgres[21517]: [1156-1] localhost LOG:  duration: 0.121 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=1700
Jul  7 12:38:21 beeb postgres[21517]: [1157-1] localhost LOG:  duration: 0.119 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=1700
Jul  7 12:38:21 beeb postgres[21517]: [1158-1] localhost LOG:  duration: 0.118 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=1700
Jul  7 12:38:21 beeb postgres[21517]: [1159-1] localhost LOG:  duration: 0.119 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=1700
Jul  7 12:38:21 beeb postgres[21517]: [1160-1] localhost LOG:  duration: 0.120 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=20
Jul  7 12:38:21 beeb postgres[21517]: [1161-1] localhost LOG:  duration: 0.119 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=1043
Jul  7 12:38:21 beeb postgres[21517]: [1162-1] localhost LOG:  duration: 0.120 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=701
Jul  7 12:38:21 beeb postgres[21517]: [1163-1] localhost LOG:  duration: 0.138 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=20
Jul  7 12:38:21 beeb postgres[21517]: [1164-1] localhost LOG:  duration: 0.122 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=21
Jul  7 12:38:21 beeb postgres[21517]: [1165-1] localhost LOG:  duration: 0.122 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=20
Jul  7 12:38:21 beeb postgres[21517]: [1166-1] localhost LOG:  duration: 0.119 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=20
Jul  7 12:38:21 beeb postgres[21517]: [1167-1] localhost LOG:  duration: 0.121 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=20
Jul  7 12:38:21 beeb postgres[21517]: [1168-1] localhost LOG:  duration: 0.118 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=20
Jul  7 12:38:21 beeb postgres[21517]: [1169-1] localhost LOG:  duration: 0.119 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=20
Jul  7 12:38:21 beeb postgres[21517]: [1170-1] localhost LOG:  duration: 0.118 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=23
Jul  7 12:38:21 beeb postgres[21517]: [1171-1] localhost LOG:  duration: 0.121 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=20
Jul  7 12:38:21 beeb postgres[21517]: [1172-1] localhost LOG:  duration: 0.118 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=21
Jul  7 12:38:21 beeb postgres[21517]: [1173-1] localhost LOG:  duration: 0.120 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=25
Jul  7 12:38:21 beeb postgres[21517]: [1174-1] localhost LOG:  duration: 0.119 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=1043
Jul  7 12:38:21 beeb postgres[21517]: [1175-1] localhost LOG:  duration: 0.119 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=1700
Jul  7 12:38:21 beeb postgres[21517]: [1176-1] localhost LOG:  duration: 0.123 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=1700
Jul  7 12:38:21 beeb postgres[21517]: [1177-1] localhost LOG:  duration: 0.118 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=1700
Jul  7 12:38:21 beeb postgres[21517]: [1178-1] localhost LOG:  duration: 0.123 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=1700
Jul  7 12:38:21 beeb postgres[21517]: [1179-1] localhost LOG:  duration: 0.119 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=21
Jul  7 12:38:21 beeb postgres[21517]: [1180-1] localhost LOG:  duration: 0.130 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=23
Jul  7 12:38:21 beeb postgres[21517]: [1181-1] localhost LOG:  duration: 0.122 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=20
Jul  7 12:38:21 beeb postgres[21517]: [1182-1] localhost LOG:  duration: 0.121 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=1043
Jul  7 12:38:21 beeb postgres[21517]: [1183-1] localhost LOG:  duration: 0.119 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=20
Jul  7 12:38:21 beeb postgres[21517]: [1184-1] localhost LOG:  duration: 0.254 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=1043
Jul  7 12:38:21 beeb postgres[21517]: [1185-1] localhost LOG:  duration: 0.122 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=21
Jul  7 12:38:21 beeb postgres[21517]: [1186-1] localhost LOG:  duration: 0.119 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=20
Jul  7 12:38:21 beeb postgres[21517]: [1187-1] localhost LOG:  duration: 0.119 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=1043
Jul  7 12:38:21 beeb postgres[21517]: [1188-1] localhost LOG:  duration: 0.123 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=1043
Jul  7 12:38:21 beeb postgres[21517]: [1189-1] localhost LOG:  duration: 0.117 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=21
Jul  7 12:38:21 beeb postgres[21517]: [1190-1] localhost LOG:  duration: 0.122 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=20
Jul  7 12:38:21 beeb postgres[21517]: [1191-1] localhost LOG:  duration: 0.117 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=20
Jul  7 12:38:21 beeb postgres[21517]: [1192-1] localhost LOG:  duration: 0.118 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=1043
Jul  7 12:38:21 beeb postgres[21517]: [1193-1] localhost LOG:  duration: 0.117 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=21
Jul  7 12:38:21 beeb postgres[21517]: [1194-1] localhost LOG:  duration: 0.117 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=21
Jul  7 12:38:21 beeb postgres[21517]: [1195-1] localhost LOG:  duration: 0.122 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=21
Jul  7 12:38:21 beeb postgres[21517]: [1196-1] localhost LOG:  duration: 0.117 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=23
Jul  7 12:38:21 beeb postgres[21517]: [1197-1] localhost LOG:  duration: 0.123 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=1043
Jul  7 12:38:21 beeb postgres[21517]: [1198-1] localhost LOG:  duration: 0.117 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=21
Jul  7 12:38:21 beeb postgres[21517]: [1199-1] localhost LOG:  duration: 0.137 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=21
Jul  7 12:38:21 beeb postgres[21517]: [1200-1] localhost LOG:  duration: 0.124 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=21
Jul  7 12:38:21 beeb postgres[21517]: [1201-1] localhost LOG:  duration: 0.124 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=701
Jul  7 12:38:21 beeb postgres[21517]: [1202-1] localhost LOG:  duration: 0.123 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=701
Jul  7 12:38:21 beeb postgres[21517]: [1203-1] localhost LOG:  duration: 0.127 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=21
Jul  7 12:38:21 beeb postgres[21517]: [1204-1] localhost LOG:  duration: 0.121 
ms  statement: SELECT TYPNAME FROM PG_TYPE WHERE OID=23

That's nothing for postgres, but quite a load for php and site. As PgFouine 
suggests I'm getting ~2kk such requests per hour:

Rank	Times executed	Total duration	Av. duration (s)	
1	2,237,202	4m49s		0.00	SELECT TYPNAME FROM PG_TYPE 
WHERE OID=0;
2	99,243		7.1s		0.00	DEALLOCATE pdo_stmt_00;

There would be much better to request all data at once, cache it and return 
afterwards. I considered session caching but this can break things if after some 
statement any type changes. Getting all data with "SELECT TYPNAME FROM PG_TYPE 
where OID IN (<id list>);" would be much faster.


Patches

Add a Patch

Pull Requests

Add a Pull Request

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2013-06-28 20:42 UTC] yohgaki@php.net
-Status: Open +Status: Analyzed -Type: Bug +Type: Feature/Change Request
 [2013-06-28 20:42 UTC] yohgaki@php.net
If we cache meta info, we need configuration api for it.
 [2016-04-05 13:43 UTC] ab@php.net
-Status: Analyzed +Status: Closed -Assigned To: +Assigned To: ab
 [2016-04-05 13:43 UTC] ab@php.net
Fixed in 7.0, see https://github.com/php/php-src/pull/1534 

Thanks.
 
PHP Copyright © 2001-2017 The PHP Group
All rights reserved.
Last updated: Tue Aug 29 15:01:52 2017 UTC