performance problem

[thenotsoft]

When creating an entity, too many requests are generated as a result the speed of work is slow.

entity has only one dependency hasOne

$user = new User('test@exemple.com');

$tr = new Transaction($orm);
$tr->persist($user);
$tr->run();

[2020-01-28T17:15:29.240219+02:00] database.INFO: Begin transaction [] []
[2020-01-28T17:15:29.244725+02:00] database.INFO: SELECT nspname FROM pg_namespace WHERE nspname !~ '^pg_.*' AND nspname != 'information_schema'; {"elapsed":0.0007541179656982422} []
[2020-01-28T17:15:29.246982+02:00] database.INFO: SELECT COUNT(table_name) FROM information_schema.tables WHERE table_schema = 'f_data'           AND table_type = 'BASE TABLE' AND table_name = 'user' {"elapsed":0.002146005630493164} []
[2020-01-28T17:15:29.248863+02:00] database.INFO: SELECT COUNT(table_name) FROM information_schema.tables WHERE table_schema = 'f_data'           AND table_type = 'BASE TABLE' AND table_name = 'user' {"elapsed":0.0007250308990478516} []
[2020-01-28T17:15:29.249161+02:00] database.INFO: SELECT oid FROM pg_class WHERE relname = 'user' {"elapsed":0.0002269744873046875} []
[2020-01-28T17:15:29.260026+02:00] database.INFO: SELECT *                         FROM information_schema.columns                         JOIN pg_type                         ON (pg_type.typname = columns.udt_name)                         WHERE table_name = 'user' {"elapsed":0.0107879638671875} []
[2020-01-28T17:15:29.262229+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{3}' {"elapsed":0.0008358955383300781} []
[2020-01-28T17:15:29.262498+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{4}' {"elapsed":0.00017714500427246094} []
[2020-01-28T17:15:29.262705+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{5}' {"elapsed":0.000125885009765625} []
[2020-01-28T17:15:29.262953+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{6}' {"elapsed":0.00016999244689941406} []
[2020-01-28T17:15:29.263203+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{7}' {"elapsed":0.0001709461212158203} []
[2020-01-28T17:15:29.263461+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{8}' {"elapsed":0.00017905235290527344} []
[2020-01-28T17:15:29.263653+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{9}' {"elapsed":0.00011396408081054688} []
[2020-01-28T17:15:29.263835+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{12}' {"elapsed":9.799003601074219e-5} []
[2020-01-28T17:15:29.263956+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{13}' {"elapsed":5.793571472167969e-5} []
[2020-01-28T17:15:29.264073+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{15}' {"elapsed":5.412101745605469e-5} []
[2020-01-28T17:15:29.264202+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{2}' {"elapsed":5.2928924560546875e-5} []
[2020-01-28T17:15:29.264315+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{3}' {"elapsed":5.1975250244140625e-5} []
[2020-01-28T17:15:29.264422+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{4}' {"elapsed":5.316734313964844e-5} []
[2020-01-28T17:15:29.264529+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{5}' {"elapsed":5.078315734863281e-5} []
[2020-01-28T17:15:29.264627+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{6}' {"elapsed":5.0067901611328125e-5} []
[2020-01-28T17:15:29.264723+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{7}' {"elapsed":4.887580871582031e-5} []
[2020-01-28T17:15:29.264828+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{9}' {"elapsed":5.0067901611328125e-5} []
[2020-01-28T17:15:29.264927+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{11}' {"elapsed":4.9114227294921875e-5} []
[2020-01-28T17:15:29.265030+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{15}' {"elapsed":4.9114227294921875e-5} []
[2020-01-28T17:15:29.265143+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{3}' {"elapsed":5.0067901611328125e-5} []
[2020-01-28T17:15:29.265239+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{4}' {"elapsed":4.887580871582031e-5} []
[2020-01-28T17:15:29.265335+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{5}' {"elapsed":4.887580871582031e-5} []
[2020-01-28T17:15:29.265430+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{6}' {"elapsed":4.9114227294921875e-5} []
[2020-01-28T17:15:29.265526+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{7}' {"elapsed":4.887580871582031e-5} []
[2020-01-28T17:15:29.265621+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{8}' {"elapsed":4.9114227294921875e-5} []
[2020-01-28T17:15:29.265721+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{9}' {"elapsed":5.2928924560546875e-5} []
[2020-01-28T17:15:29.265829+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{12}' {"elapsed":5.1021575927734375e-5} []
[2020-01-28T17:15:29.265926+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{13}' {"elapsed":4.9114227294921875e-5} []
[2020-01-28T17:15:29.266038+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 17802 AND contype = 'c' AND conkey = '{15}' {"elapsed":5.412101745605469e-5} []
[2020-01-28T17:15:29.267647+02:00] database.INFO: SELECT * FROM pg_indexes WHERE schemaname = 'f_data' AND tablename = 'user' {"elapsed":0.0015099048614501953} []
[2020-01-28T17:15:29.267911+02:00] database.INFO: SELECT contype FROM pg_constraint WHERE conname = 'user_pkey' {"elapsed":0.0001780986785888672} []
[2020-01-28T17:15:29.582315+02:00] database.INFO: SELECT tc.constraint_name, tc.table_name, kcu.column_name, rc.update_rule, rc.delete_rule, ccu.table_name AS foreign_table_name, ccu.column_name AS foreign_column_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 JOIN information_schema.referential_constraints AS rc    ON rc.constraint_name = tc.constraint_name WHERE constraint_type = 'FOREIGN KEY' AND tc.table_name = 'user' {"elapsed":0.31433701515197754} []
[2020-01-28T17:15:29.583371+02:00] database.INFO: SELECT * FROM pg_indexes WHERE schemaname = 'f_data' AND tablename = 'user' {"elapsed":0.0006330013275146484} []
[2020-01-28T17:15:29.583596+02:00] database.INFO: SELECT contype FROM pg_constraint WHERE conname = 'user_pkey' {"elapsed":0.00014495849609375} []
[2020-01-28T17:15:29.584425+02:00] database.INFO: INSERT INTO "f_data"."user" ("id", "role_id", "email", "new_email", "username", "password", "auth_key", "api_key", "share_key", "share_track", "ban_time", "ban_reason", "login_ip", "login_time", "create_ip", "status", "create_time", "update_time") VALUES (724, 5, 'test@exemple.com', NULL, NULL, NULL, NULL, NULL, NULL, 0, NULL, NULL, NULL, NULL, NULL, 0, '2020-01-28T17:15:29+02:00', '2020-01-28T17:15:29+02:00') RETURNING "id" {"elapsed":0.00036716461181640625} []
[2020-01-28T17:15:29.585477+02:00] database.INFO: SELECT COUNT(table_name) FROM information_schema.tables WHERE table_schema = 'f_data'           AND table_type = 'BASE TABLE' AND table_name = 'user_profile' {"elapsed":0.0005700588226318359} []
[2020-01-28T17:15:29.586146+02:00] database.INFO: SELECT COUNT(table_name) FROM information_schema.tables WHERE table_schema = 'f_data'           AND table_type = 'BASE TABLE' AND table_name = 'user_profile' {"elapsed":0.0005431175231933594} []
[2020-01-28T17:15:29.586443+02:00] database.INFO: SELECT oid FROM pg_class WHERE relname = 'user_profile' {"elapsed":0.0002357959747314453} []
[2020-01-28T17:15:29.591299+02:00] database.INFO: SELECT *                         FROM information_schema.columns                         JOIN pg_type                         ON (pg_type.typname = columns.udt_name)                         WHERE table_name = 'user_profile' {"elapsed":0.004782915115356445} []
[2020-01-28T17:15:29.591772+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 16628 AND contype = 'c' AND conkey = '{3}' {"elapsed":0.00021910667419433594} []
[2020-01-28T17:15:29.592009+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 16628 AND contype = 'c' AND conkey = '{4}' {"elapsed":0.00015306472778320312} []
[2020-01-28T17:15:29.592246+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 16628 AND contype = 'c' AND conkey = '{5}' {"elapsed":0.00015807151794433594} []
[2020-01-28T17:15:29.592483+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 16628 AND contype = 'c' AND conkey = '{6}' {"elapsed":0.0001590251922607422} []
[2020-01-28T17:15:29.592717+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 16628 AND contype = 'c' AND conkey = '{7}' {"elapsed":0.0001571178436279297} []
[2020-01-28T17:15:29.592919+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 16628 AND contype = 'c' AND conkey = '{8}' {"elapsed":0.0001239776611328125} []
[2020-01-28T17:15:29.593079+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 16628 AND contype = 'c' AND conkey = '{3}' {"elapsed":7.891654968261719e-5} []
[2020-01-28T17:15:29.593216+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 16628 AND contype = 'c' AND conkey = '{4}' {"elapsed":7.510185241699219e-5} []
[2020-01-28T17:15:29.593349+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 16628 AND contype = 'c' AND conkey = '{5}' {"elapsed":7.605552673339844e-5} []
[2020-01-28T17:15:29.593485+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 16628 AND contype = 'c' AND conkey = '{6}' {"elapsed":7.486343383789062e-5} []
[2020-01-28T17:15:29.593595+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 16628 AND contype = 'c' AND conkey = '{7}' {"elapsed":5.888938903808594e-5} []
[2020-01-28T17:15:29.593696+02:00] database.INFO: SELECT conname, pg_get_constraintdef(oid) as consrc FROM pg_constraint         WHERE conrelid = 16628 AND contype = 'c' AND conkey = '{8}' {"elapsed":5.1975250244140625e-5} []
[2020-01-28T17:15:29.594383+02:00] database.INFO: SELECT * FROM pg_indexes WHERE schemaname = 'f_data' AND tablename = 'user_profile' {"elapsed":0.0006208419799804688} []
[2020-01-28T17:15:29.594575+02:00] database.INFO: SELECT contype FROM pg_constraint WHERE conname = 'user_profile_pkey' {"elapsed":0.00014495849609375} []
[2020-01-28T17:15:29.903750+02:00] database.INFO: SELECT tc.constraint_name, tc.table_name, kcu.column_name, rc.update_rule, rc.delete_rule, ccu.table_name AS foreign_table_name, ccu.column_name AS foreign_column_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 JOIN information_schema.referential_constraints AS rc    ON rc.constraint_name = tc.constraint_name WHERE constraint_type = 'FOREIGN KEY' AND tc.table_name = 'user_profile' {"elapsed":0.30912208557128906} []
[2020-01-28T17:15:29.904518+02:00] database.INFO: SELECT * FROM pg_indexes WHERE schemaname = 'f_data' AND tablename = 'user_profile' {"elapsed":0.0006289482116699219} []
[2020-01-28T17:15:29.904743+02:00] database.INFO: SELECT contype FROM pg_constraint WHERE conname = 'user_profile_pkey' {"elapsed":0.00014519691467285156} []
[2020-01-28T17:15:29.905470+02:00] database.INFO: INSERT INTO "f_data"."user_profile" ("fname", "lname", "phone", "mobile", "email", "lang", "create_time", "update_time", "user_id") VALUES (NULL, NULL, NULL, NULL, NULL, NULL, '2020-01-28T17:15:29+02:00', '2020-01-28T17:15:29+02:00', 724) RETURNING "id" {"elapsed":0.0005609989166259766} []
[2020-01-28T17:15:29.905599+02:00] database.INFO: Commit transaction [] []

What could be the problem ?

[wolfy-j]

Hi, do you use it in classic or RoadRunner application?

What is happening here, the DBAL (not ORM) looks for the PK key of the table you insert into, this is because of PosgreSQL lastInsertID works differently than other databases (see RETURNING "id").

The table PK are cached in memory after first call (adapted for RoadRunner). In classic approach, we should either turn it off or provide you an option to cache this keys somewhere.

[thenotsoft]

@wolfy-j classic application yii3 with cache

[wolfy-j]

OK, I might need to talk to @roxblnfk to cache the Postgres primary keys or alter inserts... sit tight.

[wolfy-j]

In progress.

[wolfy-j]

The Postgres PK issue has been addressed in 1.2.3