RemoteColumnTypes is slow and invoked very frequently when DEV_MODE is off

[louischan-oursky]

(Describe the issue here)

• Skygear Server Date/Version: 0.24
• Application Platform:
• [X] Is this a regression?
• [X] Attached logs, screenshots

Expected Results

RemoteColumnTypes performance should be acceptable when DEV_MODE is off.

Actual Results

RemoteColumnTypes should not be too slow (it repeatedly takes more 2 seconds to complete). And it should not be invoked very frequently.

Log

2017-11-16 03:23:48 UTC:172.31.9.74(60080) duration: 2005.143 ms execute <unnamed>: SELECT kcu.column_name, ccu.table_name FROM information_schema.table_constraints AS tc JOIN information_schema.key_column_usage AS kcu ON tc.constraint_name = kcu.constraint_name JOIN information_schema.constraint_column_usage AS ccu ON ccu.constraint_name = tc.constraint_name WHERE constraint_type = 'FOREIGN KEY' AND tc.table_schema = $1 AND tc.table_name = $2

2017-11-16 03:25:03 UTC:172.31.9.74(60320) duration: 2065.730 ms execute <unnamed>: SELECT kcu.column_name, ccu.table_name FROM information_schema.table_constraints AS tc JOIN information_schema.key_column_usage AS kcu ON tc.constraint_name = kcu.constraint_name JOIN information_schema.constraint_column_usage AS ccu ON ccu.constraint_name = tc.constraint_name WHERE constraint_type = 'FOREIGN KEY' AND tc.table_schema = $1 AND tc.table_name = $2

[kitmoovup]

@louischan-oursky @carmenlau

Today we receive an alert from AWS RDS. The CPU time of PostgreSQL RDS suddenly go over 95%. I have checked the RDS log and found there are a lot of query executed during that period.

Skygear version: v0.24.0 PostgreSQL: 9.5.10

2018-03-29 02:56:50 UTC:xxx.xxx.xxx.xxx(1052):mysecret@mysecret:[22424]:LOG: duration: 2024.436 ms execute <unnamed>: SELECT kcu.column_name, ccu.table_name FROM information_schema.table_constraints AS tc JOIN information_schema.key_column_usage AS kcu ON tc.constraint_name = kcu.constraint_name JOIN information_schema.constraint_column_usage AS ccu ON ccu.constraint_name = tc.constraint_name WHERE constraint_type = 'FOREIGN KEY' AND tc.table_schema = $1 AND tc.table_name = $2
2018-03-29 02:56:50 UTC:xxx.xxx.xxx.xxx(1052):mysecret@mysecret:[22424]:DETAIL: parameters: $1 = 'app_mysecret', $2 = 'table1'
2018-03-29 02:56:50 UTC:xxx.xxx.xxx.xxx(37320):mysecret@mysecret:[22427]:LOG: duration: 2286.834 ms execute <unnamed>: SELECT kcu.column_name, ccu.table_name FROM information_schema.table_constraints AS tc JOIN information_schema.key_column_usage AS kcu ON tc.constraint_name = kcu.constraint_name JOIN information_schema.constraint_column_usage AS ccu ON ccu.constraint_name = tc.constraint_name WHERE constraint_type = 'FOREIGN KEY' AND tc.table_schema = $1 AND tc.table_name = $2
2018-03-29 02:56:50 UTC:xxx.xxx.xxx.xxx(37320):mysecret@mysecret:[22427]:DETAIL: parameters: $1 = 'app_mysecret', $2 = 'table2'
2018-03-29 02:56:51 UTC:xxx.xxx.xxx.xxx(37326):mysecret@mysecret:[22428]:LOG: duration: 2283.424 ms execute <unnamed>: SELECT kcu.column_name, ccu.table_name FROM information_schema.table_constraints AS tc JOIN information_schema.key_column_usage AS kcu ON tc.constraint_name = kcu.constraint_name JOIN information_schema.constraint_column_usage AS ccu ON ccu.constraint_name = tc.constraint_name WHERE constraint_type = 'FOREIGN KEY' AND tc.table_schema = $1 AND tc.table_name = $2
2018-03-29 02:56:51 UTC:xxx.xxx.xxx.xxx(37326):mysecret@mysecret:[22428]:DETAIL: parameters: $1 = 'app_mysecret', $2 = 'table3'
2018-03-29 02:56:51 UTC:xxx.xxx.xxx.xxx(37242):mysecret@mysecret:[22325]:LOG: duration: 2008.596 ms execute <unnamed>: SELECT kcu.column_name, ccu.table_name FROM information_schema.table_constraints AS tc JOIN information_schema.key_column_usage AS kcu ON tc.constraint_name = kcu.constraint_name JOIN information_schema.constraint_column_usage AS ccu ON ccu.constraint_name = tc.constraint_name WHERE constraint_type = 'FOREIGN KEY' AND tc.table_schema = $1 AND tc.table_name = $2
2018-03-29 02:56:51 UTC:xxx.xxx.xxx.xxx(37242):mysecret@mysecret:[22325]:DETAIL: parameters: $1 = 'app_mysecret', $2 = 'table4'

Will it be fixed in v1.4.0?

[chpapa]

Pump up the priority of this issue again.

[louischan-oursky]

@kitmoovup

This is just my guess.

The client may be trying to save a non-existing column so trigger a reflection on the database schema. Is it possible to audit your usage on skygear.publicBD.save to find out the culprit?

[kitmoovup]

@louischan-oursky

FYI, the situation happens for an hour. There is no any cronjob executing during that period. And the overall CPU time is over 50% (m3.medium). Also, I have checked the ELB request count, the request count is normal. So, I don't think that the log is triggered by client side.

[chpapa]

@kitmoovup I think what @louischan-oursky meant is it could be trigger by ONE request of non-existing column which trigger a reflection on the database scheme. So your information actually is not relevant and can’t conclude logically to “not triggered by client side”