graphile
postgraphile taking +1h to start on a simple schema
Summary
I'm deploying a postgraphile instance using Docker and Kubernetes and it takes +1h to start.
I set the debug level to track everything (https://www.graphile.org/postgraphile/debugging/) and I notice one plugin taking +1h to start
...
2022-04-01T12:18:00.518Z graphile-builder [build]: Executing 'PgIntrospectionPlugin/build/PgIntrospection'
2022-04-01T13:16:14.057Z graphile-builder [build]: 'PgIntrospectionPlugin/build/PgIntrospection' complete
...
Schema structure
Only one table with 6 fields, 1 serial, 4 cititext and 1 varchar(100).
The table contains ~110k records
How I am building the app
I'm using a Dockerfile and deploying it in kubernetes
FROM ubuntu:18.04
# install postgres and node
RUN apt-get update
RUN apt-get -y install postgresql postgresql-contrib nodejs npm
# install postgraphile
RUN npm install -g postgraphile @graphile-contrib/pg-simplify-inflector postgraphile-plugin-connection-filter
#Run script
COPY startserver.sh /
RUN chmod u+x startserver.sh
CMD bash startserver.sh
EXPOSE 5000
startserver.sh script
#!/bin/bash
export PGUSER=<my_db_user>
export PGPASSWORD=<my_db_password>
export DEBUG="postgraphile:graphql,postgraphile:request,postgraphile:postgres*,postgraphile:cli,graphile-builder,graphile-build-pg*";
postgraphile -c postgres://<my_db_server> -s <my_schema> \
--no-ignore-rbac --dynamic-json --enable-query-batching \
--append-plugins @graphile-contrib/pg-simplify-inflector,postgraphile-plugin-connection-filter \
--enhance-graphiql
Versions used
postgraphile version: 4.12.9 postgres version: 12.2
My first guess is that you're connected to a giant shared PostgreSQL server that has hundreds of thousands or even millions of database roles. Try removing the --no-ignore-rbac flag.
There are not much roles on the DB
select count(*) from pg_roles;
count
-------
25
(1 row)
On another environment the same plugin is throwing FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memory
The segment of the log
...
2022-04-04T15:59:33.421Z graphile-builder [build]: Executing 'PgIntrospectionPlugin/build/PgIntrospection'
<--- Last few GCs --->
[26:0x55fbb8fcf430] 122016 ms: Mark-sweep 1237.1 (1459.8) -> 1236.9 (1462.8) MB, 2440.4 / 0.0 ms allocation failure GC in old space requested
[26:0x55fbb8fcf430] 123644 ms: Mark-sweep 1236.9 (1462.8) -> 1236.9 (1424.3) MB, 1627.0 / 0.1 ms last resort GC in old space requested
[26:0x55fbb8fcf430] 125019 ms: Mark-sweep 1236.9 (1424.3) -> 1236.9 (1417.8) MB, 1375.2 / 0.1 ms last resort GC in old space requested
FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memory
1: node::Abort() [node]
2: 0x55fbb7a87011 [node]
3: v8::Utils::ReportOOMFailure(char const*, bool) [node]
4: v8::internal::V8::FatalProcessOutOfMemory(char const*, bool) [node]
5: v8::internal::Factory::NewFixedArray(int, v8::internal::PretenureFlag) [node]
6: v8::internal::HashTable<v8::internal::SeededNumberDictionary, v8::internal::SeededNumberDictionaryShape>::NewInternal(v8::internal::Isolate*, int, v8::internal::PretenureFlag) [node]
7: v8::internal::HashTable<v8::internal::SeededNumberDictionary, v8::internal::SeededNumberDictionaryShape>::EnsureCapacity(v8::internal::Handle<v8::internal::SeededNumberDictionary>, int, v8::internal::PretenureFlag) [node]
8: v8::internal::Dictionary<v8::internal::SeededNumberDictionary, v8::internal::SeededNumberDictionaryShape>::Add(v8::internal::Handle<v8::internal::SeededNumberDictionary>, unsigned int, v8::internal::Handle<v8::internal::Object>, v8::internal::PropertyDetails, int*) [node]
9: 0x55fbb7661744 [node]
10: v8::internal::JSObject::AddDataElement(v8::internal::Handle<v8::internal::JSObject>, unsigned int, v8::internal::Handle<v8::internal::Object>, v8::internal::PropertyAttributes, v8::internal::Object::ShouldThrow) [node]
11: v8::internal::Object::AddDataProperty(v8::internal::LookupIterator*, v8::internal::Handle<v8::internal::Object>, v8::internal::PropertyAttributes, v8::internal::Object::ShouldThrow, v8::internal::Object::StoreFromKeyed) [node]
12: v8::internal::Object::SetProperty(v8::internal::LookupIterator*, v8::internal::Handle<v8::internal::Object>, v8::internal::LanguageMode, v8::internal::Object::StoreFromKeyed) [node]
13: v8::internal::Runtime::SetObjectProperty(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, v8::internal::LanguageMode) [node]
14: v8::internal::Runtime_SetProperty(int, v8::internal::Object**, v8::internal::Isolate*) [node]
15: 0x1c13765040bd
<--- JS stacktrace --->
==== JS stack trace =========================================
Security context: 0x5a5b8618fe1 <JSObject>
1: /* anonymous */(aka /* anonymous */) [/usr/local/lib/node_modules/postgraphile/node_modules/graphile-build-pg/node8plus/plugins/PgIntrospectionPlugin.js:~566] [pc=0x1c137668b6c0](this=0x5a5b8602241 <undefined>,memo=0x548e9102289 <Object map = 0x15694765d749>,x=0xaff68bb1191 <Object map = 0x1c1bb1972b41>)
2: arguments adaptor frame: 4->2
3: reduce(this=0x214a49782281 <JSArray[491175...
startserver.sh: line 44: 26 Aborted (core dumped) postgraphile -c postgres://$database_endpoint -s <schema> --no-ignore-rbac --dynamic-json --enable-query-batching --append-plugins @graphile-contrib/pg-simplify-inflector,postgraphile-plugin-connection-filter --disable-graphiql
Try running the introspection query yourself (you may need to put in a couple of edits): https://github.com/graphile/graphile-engine/blob/v4/packages/graphile-build-pg/src/plugins/introspectionQuery.js - I suspect something weird is going on inside your Postgres for some reason.
Unless you're running node with some special CLI flags or similar?
ubuntu 18.04 with node from RUN apt-get -y install postgresql postgresql-contrib nodejs npm gets the ancient node 8. Add the ppa for node 16 to cover if it's some ecosystem bug.
Does the premade graphile/postgraphile image still timeout too?
[semi-automated message] Hi, there has been no activity in this issue for a while so I'm closing it to keep the issues/pull requests manageable. If this is still an issue, please re-open with additional details.