IRC log for #evergreen, 2022-06-03

All times shown according to the server's local time.

Time	Nick	Message
06:01	pinesol	News from qatests: Failed Running perl live tests <http://testing.evergreen-ils.org/~live//archive/2022-06/2022-06-03_04:00:04/test.49.html>
07:16		rjackson_isl_hom joined #evergreen
07:42		collum joined #evergreen
08:05		RFrasur joined #evergreen
08:12		mantis1 joined #evergreen
08:35		mmorgan joined #evergreen
09:36		jvwoolf joined #evergreen
09:49		jvwoolf joined #evergreen
10:00		Dyrcona joined #evergreen
12:25	Bmagic	@coffee [someone]
12:25	* pinesol	brews and pours a cup of Colombia La Escuelita, and sends it sliding down the bar to ejk
12:34	berick	@coffee [band]
12:34	* pinesol	brews and pours a cup of Colombia Huila Supremo, and sends it sliding down the bar to Character Set
14:14	jeffdavis	unapi.metabib_virtual_record_feed is incredibly slow in our production database: ~30 seconds to return results for 10 records, ~2s for a single record. In a Concerto db I get results for 10 records in less than 1s.
14:27	Dyrcona	Probably needs an index on something.
15:22	jeffdavis	No, it's weirder than that I think.
15:22	jeffdavis	It's actually the call to unapi.mmr_holdings_xml from within unapi.metabib_virtual_record_feed that's slow.
15:23	jeffdavis	unapi.mmr_holdings_xml takes ~23s for my test query ... but an SQL query that ought to be equivalent to that function takes <1s
15:25	Dyrcona	You say the query is "equivalent." Is it identical to the one used in the function?
15:29	jeffdavis	looks like our version of unapi.mmr_holdings_xml uses evergreen.array_remove_item_by_value in a few places instead of array_remove
15:30	jeffdavis	I'll see if I can make things more exact
15:31	Dyrcona	Ours uses array_remove.
15:41	jeffdavis	no significant difference either way
15:44	Dyrcona	The look a bit complicated to run, so I haven't tried them today.
15:45	Dyrcona	Have you tried the functions/queries with EXPLAIN?
15:52	jeffdavis	yeah, but unfortunately it's the function that's slow and EXPLAIN doesn't show the guts of that
15:52	jeffdavis	https://pastebin.com/FpBXFGwB
15:53	jeffdavis	^ that's the function and the hopefully-equivalent query
15:55	Dyrcona	The output of explain is not there.
15:56	Dyrcona	Also, debugging Pg functions can be tricky. DB performance often feels too much like magic to me.
15:57	jeffdavis	https://pastebin.com/XiwrRpgF <- with explain output
16:00	Dyrcona	It's almost like there's a 1.5 second penalty for calling the function.
16:00	Dyrcona	Planning time is about the same.
16:05	Dyrcona	I wonder if there is a 150 ms hit for each call to the function? That would explain 1.5 seconds for 10 items in the array.
16:07	Dyrcona	That seems crazy to me though, but I can't think of any other reason for the performance to be so different.
16:11	jeffdavis	ah, there's a 2.5s penalty for every additional element in the array
16:14	jeffdavis	hm let me double check this
16:15	Dyrcona	I wonder if messing with the function's volatility will change things? It's "stable" in my db.
16:16	Dyrcona	It's also marked parallel unsafe in my Pg 10 db. I wonder if it really is.
16:21	jeffdavis	volatility=stable and parallel=unsafe in both my prod db and in a concerto db
16:23	jeffdavis	(the function is quite fast on a concerto db, 150ms execution time)
16:23	jeffdavis	I note the unapi.mmr_holdings_xml function is owned by the postgres role in the prod db, rather than by the evergreen role
16:24	Dyrcona	That might be something. Ours is owned by evergreen.
16:24	Dyrcona	I think you alter the function to change the owner.
16:25	Dyrcona	Yeah, ALTER FUNCTION name [ ( [ [ argmode ] [ argname ] argtype [, ...] ] ) ] OWNER TO { new_owner \| CURRENT_USER \| SESSION_USER }
16:27		jvwoolf left #evergreen
16:28	jeffdavis	unfortunately it doesn't help - changed the owner to evergreen in a test env and the function is still slow
16:32	jeffdavis	modifying it to use array_remove doesn't help either
16:36	Dyrcona	That's puzzling. It seems like a crazy hit to take for calling a function.
16:40	jeffdavis	yeah seems to be 2.5s per item in the array
16:43	Dyrcona	jeffdavis: You could try asking in #postgresql. Somebody there might have some idea what's going on.
16:44	jeffdavis	Good idea. Thanks for the help!
16:59		mmorgan left #evergreen
18:00	pinesol	News from qatests: Failed Running perl live tests <http://testing.evergreen-ils.org/~live//archive/2022-06/2022-06-03_16:00:02/test.49.html>