API Queries peg VM CPU

[bdbrassart]

Good Morning.

I first off apologize if I don't provide enough information initially, I've tried to compile what I think may be useful, but it's likely I've missed something important.

I built a PHP interface using the API for some of our non-tech savvy supervisors to use to help simplify a few tasks they need to do before every shift. Before every shift, they assign users to locations, and check out assets to those users.

I've also got another PHP page that queries the API every 30 seconds to display a "current status" of all assets in a particular category on a television. There are about 60 assets in that category.

I've noticed that with any API query, the apache process on our ubuntu VM pegs the processor on our VM to 100, despite how many cores we give it. Put 3 or 4 supervisors interacting with the shift lineup page at once, combined with the 30 second poll of the current status page, and it makes the entire thing very slow and almost unusable.

Looking at the apache access.log, I'm only seeing API GET requests from the web server hosting the php pages doing the polls, and I'm not seeing anything that indicates an accidental PHP loop sending more than necessary GET requests, as I'm only seeing a request every 30s on the status page, and then appropriate amount of traffic when interacting with the shift lineup.

I notice zero affect to the standard snipeit interface while this is going on. Normal usage of the snipeit interface does not affect the apache process this way.

I've enabled mysql slow query logging, and set the query time to 5 seconds, and nothing is showing in the log.

Both PHP pages are hosted on an IIS webserver, and Snipeit is installed on an Ubuntu VM running 16.04.

Snipeit version information is:

Snipe-IT version | v4.7.8  build 4170 (g4fe689dc5)
Software License | AGPL3
PHP Version | 7.2.24-1+ubuntu16.04.1+deb.sury.org+1
Laravel Version | 5.5.47

Didn't see anything in other discussions or bugs about this, so I'm posting something new. Hope that's OK.

At a bit of a loss on troubleshooting at this point -- any direction is appreciated.

[snipe]

Can you explain a little more about which API calls are pinning the CPU? What's the per-page limit on the API calls, how many items are you returning at one time, etc?

Also have you tried upgrading to v5?

[snipe]

@bdbrassart Thanks so much for the kind words <3

My guess here would be there might be an infinite loop somewhere. Like, if you use locations, maybe a child location is its own grandmother, etc. Weird recursion is the only thing I can think of that would cause this.

Is there any info you can give about your data?

[bdbrassart]

Well, the main category I'm working with is vehicles, and each vehicle has a number of assets assigned to it -- computer, monitor, keyboard, cellular router, etc... and at the beginning of each shift, supervisors check out the vehicles to users, and assign users to locations, depending on where the user and associated vehicle is assigned. I believe the checking out action automatically updates the vehicle's location to the assignee's location.

All of the locations I use are child locations of one parent, and as part of my PHP interface, when a vehicle is checked in after a shift, it reverts to another top level location.

i.e.

Location : CompanyName (No Parent)
Location : Assignments (No Parent)
Location : Loc1 (Assignments Parent)
Location : Loc2 (Assignments Parent)

There are about 15 child locations under the Assignments location, and I'm not utilizing parent-child locations in any other fashion throughout my implementation.

All the vehicle assets have either a child location (Loc1, Loc2, Loc3, etc...), the CompanyName location, or no location assigned at all.

I'll look into maybe logging mysql activity when I do the API polls, to see if I can see any kind of loop?

Would one of these recursion loops be able to happen with asset assignment maybe?

[bdbrassart]

Did some query logging and it looks like the following query takes about 10 seconds, and based on the log, when I view the "problem category" it runs this query twice:

2021-04-20 09:46:21.443890 | snipeit[snipeit] @ localhost [] | 238115 | 0 | Prepare | select * from `action_logs` where `item_type` = ? and `action_logs`.`item_id` in (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) order by `created_at` desc

2021-04-20 09:46:21.444191 | snipeit[snipeit] @ localhost [] | 238115 | 0 | Execute | select * from `action_logs` where `item_type` = 'App\\Models\\Asset' and `action_logs`.`item_id` in (2334, 2335, 2336, 2337, 2338, 2339, 2340, 2341, 2342, 2343, 2344, 2345, 2346, 2347, 2348, 2349, 2350, 2351, 2352, 2353, 2354, 2355, 2357, 2359, 2360, 2362, 2363, 2365, 2366, 2367, 2371, 2372, 2373, 2374, 2375, 2376, 2377, 2379, 2380, 2381, 2382, 2383, 2384, 2385, 2387, 2389, 2390, 2393, 2399, 2400, 2401, 2402, 2404, 2405, 2428, 2433, 2654, 2937, 2944) order by `created_at` desc

2021-04-20 09:46:21.696914 | snipeit[snipeit] @ localhost [] | 238115 | 0 | Close stmt

I'm getting the 10 second timing from the timestamp on logs from general_log, the next event happens at 2021-04-20 09:46:30. If I run that query in mysql, it takes very little time (certainty not 10 seconds) and returns about 25k rows.

I also re-created the same prepare/execute statement in mySQL and ran it from the command line:

prepare stmt1 from 'select * from `action_logs` where `item_type` = ? and `action_logs`.`item_id` in (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) order by `created_at` desc'

SET @a = 'App\\Models\\Asset';
SET @b = 2334;
SET @c = 2335; 
SET @d = 2336; 
SET @e = 2337; 
SET @f = 2338; 
SET @g = 2339; 
SET @h = 2340; 
SET @i = 2341; 
SET @j = 2342; 
SET @k = 2343; 
SET @l = 2344; 
SET @m = 2345; 
SET @n = 2346; 
SET @o = 2347; 
SET @p = 2348; 
SET @q = 2349; 
SET @r = 2350; 
SET @s = 2351; 
SET @t = 2352; 
SET @u = 2353; 
SET @v = 2354; 
SET @w = 2355; 
SET @x = 2357; 
SET @y = 2359; 
SET @z = 2360; 
SET @aa = 2362; 
SET @ab = 2363; 
SET @ac = 2365; 
SET @ad = 2366; 
SET @ae = 2367; 
SET @af = 2371; 
SET @ag = 2372; 
SET @ah = 2373; 
SET @ai = 2374; 
SET @aj = 2375; 
SET @ak = 2376; 
SET @al = 2377; 
SET @am = 2379; 
SET @an = 2380; 
SET @ao = 2381; 
SET @ap = 2382; 
SET @aq = 2383; 
SET @ar = 2384; 
SET @as = 2385; 
SET @at = 2387; 
SET @au = 2389; 
SET @av = 2390; 
SET @aw = 2393; 
SET @ax = 2399; 
SET @ay = 2400; 
SET @az = 2401; 
SET @ba = 2402; 
SET @bb = 2404; 
SET @bc = 2405; 
SET @bd = 2428; 
SET @be = 2433; 
SET @bf = 2654; 
SET @bg = 2937; 
SET @bh = 2944;
 
execute stmt1 using @a, @b, @c, @d, @e, @f, @g, @h, @i, @j, @k, @l, @m, @n, @o, @p, @q, @r, @s, @t, @u, @v, @w, @x, @y, @z, @aa, @ab, @ac, @ad, @ae, @af, @ag, @ah, @ai, @aj, @ak, @al, @am, @an, @ao, @ap, @aq, @ar, @as, @at, @au, @av, @aw, @ax, @ay, @az, @ba, @bb, @bc, @bd, @be, @bf, @bg, @bh;

I'm not super well versed in mySQL, so that might not be an accurate re-creation, but the query time was very fast when doing it that way.

I did find this mySQL bug: https://bugs.mysql.com/bug.php?id=73056, not sure if it's applicable, as the parameters in this query don't approach the 64k limit, but in the bug report, the query took 265 seconds, so maybe I'm just seeing a smaller-scale implementation of the bug?

[bdbrassart]

Also, each of these vehicle assets have anywhere from 600-1000 history items, since they get checked in and out several times a day.

Since the query it's having trouble with is action logs, could that be part of the situation?

[bdbrassart]

Just FYI, this issue resolved itself by an update to v5.1.5, the most current at the time of this posting.

[bdbrassart]

This issue resolved itself by an update to v5.1.5, the most current at the time of this posting.