Bug #62498 [NEW]: pdo_pgsql inefficient when getColumnMeta() is used

From: c dot kworr at gmail dot com Operating system: FreeBSD 9.0 PHP version: 5.3.14 Package: PostgreSQL related Bug Type: Bug Bug description:pdo_pgsql inefficient when getColumnMeta() is used 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. -- Edit bug report at https://bugs.php.net/bug.php?id=62498&edit=1 -- Try a snapshot (PHP 5.4): https://bugs.php.net/fix.php?id=62498&r=trysnapshot54 Try a snapshot (PHP 5.3): https://bugs.php.net/fix.php?id=62498&r=trysnapshot53 Try a snapshot (trunk): https://bugs.php.net/fix.php?id=62498&r=trysnapshottrunk Fixed in SVN: https://bugs.php.net/fix.php?id=62498&r=fixed Fixed in SVN and need be documented: https://bugs.php.net/fix.php?id=62498&r=needdocs Fixed in release: https://bugs.php.net/fix.php?id=62498&r=alreadyfixed Need backtrace: https://bugs.php.net/fix.php?id=62498&r=needtrace Need Reproduce Script: https://bugs.php.net/fix.php?id=62498&r=needscript Try newer version: https://bugs.php.net/fix.php?id=62498&r=oldversion Not developer issue: https://bugs.php.net/fix.php?id=62498&r=support Expected behavior: https://bugs.php.net/fix.php?id=62498&r=notwrong Not enough info: https://bugs.php.net/fix.php?id=62498&r=notenoughinfo Submitted twice: https://bugs.php.net/fix.php?id=62498&r=submittedtwice register_globals: https://bugs.php.net/fix.php?id=62498&r=globals PHP 4 support discontinued: https://bugs.php.net/fix.php?id=62498&r=php4 Daylight Savings: https://bugs.php.net/fix.php?id=62498&r=dst IIS Stability: https://bugs.php.net/fix.php?id=62498&r=isapi Install GNU Sed: https://bugs.php.net/fix.php?id=62498&r=gnused Floating point limitations: https://bugs.php.net/fix.php?id=62498&r=float No Zend Extensions: https://bugs.php.net/fix.php?id=62498&r=nozend MySQL Configuration Error: https://bugs.php.net/fix.php?id=62498&r=mysqlcfg