| Time |
Nick |
Message |
| 07:57 |
|
genpaku joined #evergreen |
| 08:39 |
|
mmorgan joined #evergreen |
| 09:11 |
Bmagic |
Dyrcona: Are you still working on bug 1928126? |
| 09:11 |
Bmagic |
ha, he's not here |
| 09:11 |
Bmagic |
@later tell Dyrcona: Are you still working on bug 1928126? |
| 09:11 |
pinesol |
Bmagic: The operation succeeded. |
| 10:29 |
csharp_ |
gimme some-a that XUL |
| 10:29 |
csharp_ |
wishlist bug: go back to the XUL client |
| 10:34 |
|
Dyrcona joined #evergreen |
| 10:42 |
|
kmlussier joined #evergreen |
| 11:07 |
|
jihpringle joined #evergreen |
| 12:03 |
Dyrcona |
csharp_: I tested my srfsh fix on Ubuntu 24.04 with libreadline 8.2 and srfsh still works. |
| 12:09 |
csharp_ |
excellent |
| 12:11 |
Dyrcona |
On the upgraded machine where osrf_control hangs, I just noticed something. I think it's hanging trying to start opensrf.math, because if I interrupt osrf_control, opensrf.math is not running. |
| 12:16 |
Dyrcona |
Yeahp. If I just start the router and then start opensrf.math, the second hangs. |
| 12:19 |
* Dyrcona |
tries rm /openils/lib* and git clean -xfd to build it all again. |
| 12:22 |
Dyrcona |
Nope. it still seems to hang. |
| 12:23 |
Dyrcona |
opensrf.dbmath also hangs. |
| 12:27 |
Dyrcona |
maybe have a wishlist for opensrf-perl.pl: An option to list the configured services by host. |
| 12:28 |
Dyrcona |
`osrf_control -l --list-services` to list the services configured in opensrf.xml. Maybe the router and opensrf.settings would need to be running? |
| 12:32 |
Dyrcona |
So, that narrows it down to the C services not starting. The Perl opensrf services start. IIRC, I did install Evergreen on this upgraded machine and the Evergreen C services worked, but I suppose I could try that again. |
| 12:33 |
Dyrcona |
And, this is only happening on a vm upgraded from Ubuntu 24.04 to Ubuntu 26.04 that had OpenSRF and Evergreen previously installed, but has also had /openils/* essentially rm'd in the meantime. |
| 12:34 |
Bmagic |
here's a fun rabbit hole: /eg/staff/circ/holds/pull (the old AngularJS pull list) is fast for one user and slow for another. Same everything, same permissions, same staff account in all ways except username. It's a query slowness. The two queires are identical except the User ID number passed. Here's the query: https://pastebin.com/ykLedMeK |
| 12:35 |
Bmagic |
if you swap out the user ID number 490, for the other staff account ID number, the query goes from 40 seconds to 2 seconds. The function is permission.usr_has_object_perm(490, 'VIEW_HOLD', 'ahopl', "ahopl"."id"::TEXT, pickup_lib |
| 12:38 |
Bmagic |
Postgres is taking 38 more seconds to "lookup" VIEW_HOLD for one staff member compared to the other staff member. When executing that function all by itself, it's fast! For both users |
| 12:41 |
Dyrcona |
Bmagic: How many permission.usr_perm_map, permission.usr_grp_map, and permission.usr_work_ou_map entries per user. If the one taking longer has more, then maybe one of the tables needs a vacuum or reindex. |
| 12:41 |
Bmagic |
that's probably the right track, let me check |
| 12:42 |
Dyrcona |
Those tables don't usually change much, though. |
| 12:56 |
Bmagic |
found it! it's the super_user column |
| 12:57 |
Bmagic |
from the function: IF r_usr.super_user = TRUE THEN RETURN TRUE; END IF; |
| 12:57 |
Dyrcona |
We should remove that column. |
| 12:57 |
Bmagic |
the fast user had super_user set to true, and the slow user didn't which means the slow user was executing more SQL |
| 12:58 |
Bmagic |
specifically this: SELECT TRUE INTO res FROM permission.usr_object_perm_map WHERE perm = r_perm.id AND usr = r_usr.id AND object_type = obj_type AND object_id = obj_id; |
| 12:59 |
Dyrcona |
I'd check the indexes on that table, maybe run it through explain. Might find a different index definition that could speed it up. |
| 13:00 |
Bmagic |
running that function takes the exact same amount of time for each user, just when it's wrapped inside that bigger query, it does wrecks PG |
| 13:01 |
Bmagic |
/does// |
| 13:02 |
goood |
Bmagic: are the plans structured differently? if it's inlining that big stack of PLSQL functions, that'd be painful, potentially |
| 13:03 |
Bmagic |
goood: that doesn't seem to matter because when I change the user ID (and that's all I do to the query) it goes from fast to slow |
| 13:03 |
goood |
(and I'm willing to bet that permission.usr_object_perm_map is basically empty) |
| 13:03 |
goood |
um, what do you mean it doesn't change the query? |
| 13:04 |
Bmagic |
I've captured the query from the PG log, and ran it by hand. Not changing anything but the User ID, I can recreate the slow/fast |
| 13:04 |
goood |
every query has to be planned. I'm talking about the query plan structure. |
| 13:05 |
Bmagic |
I thought you were talking about the order in which the query was generated in the perl. There is* a difference that I captured in PG when running through the interface for each user, and I originally thought that could be the issue. It wasn't |
| 13:06 |
goood |
no, "are the plans structured differently" |
| 13:07 |
Bmagic |
https://explain.dalibo.com/plan/ce1669e2a9b96ga5#plan/node/28 |
| 13:07 |
Bmagic |
vs https://explain.dalibo.com/plan/ed32d1g19b2576b7 |
| 13:13 |
goood |
yeah, they're different. just visually, jumping to the bottom, the fast one is a node shorter, has a index scan on copy location over a much shorter list (copy locations filtered earlier). |
| 13:13 |
goood |
looking at them on depesz, fwiw |
| 13:14 |
goood |
slow https://explain.depesz.com/s/95Lt vs fast https://explain.depesz.com/s/sZj4 |
| 13:15 |
goood |
look at node 28 (first) vs node 23 (second); heap scan vs index scan |
| 13:17 |
Bmagic |
yep, and PG decided that based on how long permission.usr_has_object_perm is predicted to take? I wonder |
| 13:18 |
Bmagic |
it's the exact same query with the ID swapped out, so I can only conclude that PG "knows" something about the outcome of permission.usr_has_object_perm for one ID vs. the other |
| 13:22 |
Dyrcona |
The presence of the super_user = true probably means the planner can skip a step or two. |
| 13:23 |
Bmagic |
It's amazing to me that PG would inspect the function that closely prior to making the plan, but PG is amazing |
| 13:24 |
Dyrcona |
I don't pretend to know how the planner works. I just know it has become way more sophisticated over the years and Pg releases. |
| 13:25 |
Dyrcona |
OK. Back to OpenSRF debugging. |
| 13:26 |
Bmagic |
so the super_user column does seem antiquated at this point? It existed in a land before time? |
| 13:26 |
Dyrcona |
I seem to recall that there is a Launchpad or some other discussion about removing it. Doing so would require touching a number of database functions. |
| 13:27 |
Dyrcona |
I think it existed before the EVERYTHING permission. |
| 13:27 |
goood |
it did |
| 13:28 |
Dyrcona |
Ah stole my thunder. I was making an Elrond reference. :) |
| 13:28 |
Bmagic |
greping the code, I love seeing the lines for super_user, setting there in the file, rooted there for 22 years |
| 13:29 |
Dyrcona |
Well, I'm for getting rid of the super_user field. |
| 13:31 |
goood |
Bmagic: you could try adjusting the function cost, both up and down. begin; alter function permission.usr_has_object_perm(int,text,text,text,int) cost 1; EXPLAIN ANALYZE SELECT ...; rollback; ... and separately, the same but with "cost 1000" |
| 13:31 |
goood |
that can be run live, if you keep the begin/rollback wrapper |
| 13:31 |
Bmagic |
alright, I'll give it a shot |
| 13:34 |
Bmagic |
cost 1: 20.1 seconds, cost 1000: 20.01 seconds |
| 13:36 |
goood |
so, not that |
| 13:36 |
Bmagic |
didn't seem to make a difference |
| 13:37 |
goood |
but that's better than 40s, without seeing the plan changes (which, right now, I don't have time to investigate ... sorry) |
| 13:37 |
Bmagic |
no worries |
| 13:37 |
Bmagic |
I'm happy with the super_user discovery, though the issue is more of a PG planning issue regardless of super_user |
| 13:39 |
Bmagic |
cost 1 version: https://explain.depesz.com/s/ZsPn cost 1000: https://explain.depesz.com/s/SVaj |
| 13:40 |
goood |
(final note: you might have to adjust the cost of the other functions that /that/ one calls, several of them. that may not have any impact, though, if it's scrobling through the function plans) |
| 13:40 |
|
jihpringle joined #evergreen |
| 13:40 |
Bmagic |
goood: thanks! I'll go deeper |
| 13:41 |
goood |
oh, that def changed the estimated cost of the plans! see the first node's cost= value in each |
| 13:51 |
Dyrcona |
I suppose that I should also debug this on a system where the c services do not hang. I just saw something that "bothers" me while starting opensr.math. It skipped the `if (is_service)` block, and I'm not sure if that's expected or not. |
| 13:55 |
Dyrcona |
Line 202 of osrf_system.c `retcode = osrf_settings_retrive(hostname);` takes a while. I should step into that. |
| 13:56 |
Dyrcona |
Meh. Accidentally stepped into malloc(). |
| 14:06 |
Dyrcona |
line 113 in osrf_settings.c is where the trouble seems to lie. |
| 14:13 |
Dyrcona |
I just realized that line isn't the problem. The manual debugging is slowing things down so much that the connection to the settings service timed out. |
| 14:17 |
Dyrcona |
Looks like something to do with redis on an upgraded system. I wonder if it is redis configuration? |
| 14:22 |
Dyrcona |
redis.conf is the same on both vms. |
| 15:03 |
|
jihpringle joined #evergreen |
| 15:36 |
|
jihpringle joined #evergreen |
| 17:07 |
|
kmlussier left #evergreen |
| 17:10 |
|
mmorgan left #evergreen |
| 17:55 |
|
jihpringle joined #evergreen |
| 18:40 |
|
jihpringle joined #evergreen |
| 19:49 |
|
jihpringle joined #evergreen |
