CDLUC3 / ezid

CDLUC3 ezid
MIT License
10 stars 4 forks source link

Refactor proc-link-checker #675

Open jsjiang opened 4 months ago

jsjiang commented 4 months ago

The proc-link-checker background job is memory intensive on the RDS server. The core SQL query is identified as one of the long running queries. Refactor the process to make the SQL queries more efficient. Or consider to use OpenSearch as data sources.

Also, the job reschedules itself to run at the same time a week later.

Refactor items:

jsjiang commented 3 months ago

The link checker job by proc-link-chekcer.py might have contributed to this long waits query:

SELECT `ezidapp_searchidentifier` . `id` , `ezidapp_searchidentifier` . `identifier` , `ezidapp_searchidentifier` . `owner_id` , `ezidapp_searchidentifier` . `status` , `ezidapp_searchidentifier` . `target` , `ezidapp_searchidentifier` . `isTest` FROM `ezidapp_searchidentifier` WHERE `ezidapp_searchidentifier` . `identifier` > ? ORDER BY `ezidapp_searchidentifier` . `identifier` ASC LIMIT ?

SELECT `ezidapp_searchidentifier`.`id`, `ezidapp_searchidentifier`.`identifier`, `ezidapp_searchidentifier`.`owner_id`, `ezidapp_searchidentifier`.`status`, `ezidapp_searchidentifier`.`target`, `ezidapp_searchidentifier`.`isTest` FROM `ezidapp_searchidentifier` WHERE `ezidapp_searchidentifier`.`identifier` > 'ark:/88122/gnch0276' ORDER BY `ezidapp_searchidentifier`.`identifier` ASC LIMIT 1000

proc-link-chekcer.py:

        search_identifier_model = django.apps.apps.get_model('ezidapp', 'SearchIdentifier')
        siGenerator = self.harvest(
            search_identifier_model,
            ["identifier", "owner", "status", "target", "isTest"],
            lambda si: si.isPublic
            and not si.isTest
            and si.target != si.defaultTarget
            and si.owner_id not in self._permanentExcludes,
        )
jsjiang commented 3 months ago

RDS performance 2024-08-20, with avg latency=302.67, rows examined=999.96

lonk-checker-2024-0820

Query group

SELECT `ezidapp_searchidentifier` . `id` , `ezidapp_searchidentifier` . `identifier` , `ezidapp_searchidentifier` . `owner_id` , `ezidapp_searchidentifier` . `status` , `ezidapp_searchidentifier` . `target` , `ezidapp_searchidentifier` . `isTest` FROM `ezidapp_searchidentifier` WHERE `ezidapp_searchidentifier` . `identifier` > ? ORDER BY `ezidapp_searchidentifier` . `identifier` ASC LIMIT ?

SELECT `ezidapp_searchidentifier`.`id`, `ezidapp_searchidentifier`.`identifier`, `ezidapp_searchidentifier`.`owner_id`, `ezidapp_searchidentifier`.`status`, `ezidapp_searchidentifier`.`target`, `ezidapp_searchidentifier`.`isTest` FROM `ezidapp_searchidentifier` WHERE `ezidapp_searchidentifier`.`identifier` > 'ark:/88122/fhfc0000' ORDER BY `ezidapp_searchidentifier`.`identifier` ASC LIMIT 1000
jsjiang commented 2 months ago

link-checker log on Sept 16: the link checker process was restarted shortly at 8am that morning.

ezid@uc3-ezidui-prd01:16:54:01:~/logs/background_jobs$ zcat  ezid-proc-error.log-20240916.gz | grep "proc-link-checker " | grep -v HTTPError | grep -v Exception
Sep 16 08:13:23 uc3-ezidui-prd01 ezid-proc-errorlog[233529]:    INFO ezidapp.management.commands.proc-link-checker 139955763322880: end processing, checked 6114 links at 2.2 links/s, slept 03:00:00
Sep 16 08:13:25 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin update table
Sep 16 14:04:26 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end processing, checked 9617 links at 1.5 links/s, slept 07:00:00
Sep 16 14:04:26 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin load workset
Sep 16 14:04:28 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end load workset, 60 owners (15 capped), 8714 links, 1335 unvisited links, 2919 good links (oldest=79d), 4460 bad links (oldest=2d)
Sep 16 14:04:28 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin processing
Sep 16 14:54:48 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end processing, checked 8303 links at 2.7 links/s, slept 03:00:00
Sep 16 14:54:48 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin load workset
Sep 16 14:54:50 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end load workset, 20 owners (14 capped), 7407 links, 1484 unvisited links, 2346 good links (oldest=127d), 3577 bad links (oldest=2d)
Sep 16 14:54:50 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin processing
Sep 16 15:44:52 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end processing, checked 7005 links at 2.3 links/s, slept 03:00:00
Sep 16 15:44:52 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin load workset
Sep 16 15:44:54 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end load workset, 20 owners (12 capped), 6531 links, 1654 unvisited links, 2697 good links (oldest=127d), 2180 bad links (oldest=2d)
Sep 16 15:44:54 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin processing
Sep 16 16:35:15 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end processing, checked 6217 links at 2.1 links/s, slept 03:00:00
Sep 16 16:35:15 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin load workset
Sep 16 16:35:16 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end load workset, 17 owners (12 capped), 6395 links, 1384 unvisited links, 3006 good links (oldest=127d), 2005 bad links (oldest=2d)
Sep 16 16:35:16 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin processing
Sep 16 17:25:18 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end processing, checked 5917 links at 2.0 links/s, slept 03:00:00
Sep 16 17:25:18 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin load workset
Sep 16 17:25:19 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end load workset, 17 owners (12 capped), 6432 links, 1000 unvisited links, 3432 good links (oldest=127d), 2000 bad links (oldest=2d)
Sep 16 17:25:19 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin processing
Sep 16 18:15:21 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end processing, checked 6098 links at 2.0 links/s, slept 03:00:00
Sep 16 18:15:21 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin load workset
Sep 16 18:15:24 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end load workset, 16 owners (12 capped), 6354 links, 1000 unvisited links, 3352 good links (oldest=127d), 2002 bad links (oldest=2d)
Sep 16 18:15:24 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin processing
Sep 16 19:05:25 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end processing, checked 6076 links at 2.0 links/s, slept 03:00:00
Sep 16 19:05:25 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin load workset
Sep 16 19:05:28 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end load workset, 18 owners (12 capped), 6327 links, 1000 unvisited links, 3318 good links (oldest=127d), 2009 bad links (oldest=2d)
Sep 16 19:05:28 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin processing
Sep 16 19:55:32 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end processing, checked 6022 links at 2.0 links/s, slept 03:00:00
Sep 16 19:55:32 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin load workset
Sep 16 19:55:36 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end load workset, 24 owners (12 capped), 6579 links, 1000 unvisited links, 3576 good links (oldest=127d), 2003 bad links (oldest=2d)
Sep 16 19:55:36 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin processing
Sep 16 20:45:49 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end processing, checked 6157 links at 2.0 links/s, slept 03:00:00
Sep 16 20:45:49 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin load workset
Sep 16 20:45:53 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end load workset, 23 owners (12 capped), 7322 links, 998 unvisited links, 3043 good links (oldest=127d), 3281 bad links (oldest=2d)
Sep 16 20:45:53 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin processing
Sep 16 21:35:54 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end processing, checked 6946 links at 2.3 links/s, slept 03:00:00
Sep 16 21:35:54 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin load workset
Sep 16 22:25:59 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end processing, checked 6189 links at 2.1 links/s, slept 03:00:00
Sep 16 22:25:59 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin load workset
Sep 16 22:26:01 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end load workset, 80 owners (12 capped), 7182 links, 994 unvisited links, 2812 good links (oldest=127d), 3376 bad links (oldest=2d)
Sep 16 22:26:01 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin processing
Sep 16 23:16:07 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end processing, checked 6636 links at 2.2 links/s, slept 03:00:00
Sep 16 23:16:07 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin load workset
Sep 16 23:16:09 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end load workset, 51 owners (12 capped), 7757 links, 954 unvisited links, 2646 good links (oldest=127d), 4157 bad links (oldest=2d)
Sep 16 23:16:09 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin processing

RDS performance insights shows the link checker report was performed 4 hours from 8:15am to 12:25pm:

Image

jsjiang commented 2 months ago

The link-checker log on Sept 23: the report was restarted at 8:15am and finished around 12:20pm.

link-checker_2024-09-23_select

link-checker-2024-09-23_update

jsjiang commented 2 months ago

EZID log shows that a workset is processed every 50 minutes:

ezid@uc3-ezidui-prd01:15:47:53:~/logs/background_jobs$ grep -i "proc-link-checker "  ezid-proc-error.log | grep -v ERROR
Sep 23 04:59:45 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end processing, checked 6872 links at 2.3 links/s, slept 03:00:00
Sep 23 04:59:45 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin load workset
Sep 23 04:59:48 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end load workset, 17 owners (11 capped), 6890 links, 1136 unvisited links, 2904 good links (oldest=126d), 2850 bad links (oldest=2d)
Sep 23 04:59:48 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin processing
Sep 23 05:49:49 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end processing, checked 6485 links at 2.2 links/s, slept 03:00:00
Sep 23 05:49:49 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin load workset
Sep 23 05:49:51 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end load workset, 15 owners (11 capped), 6121 links, 1179 unvisited links, 3095 good links (oldest=126d), 1847 bad links (oldest=2d)
Sep 23 05:49:51 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin processing
Sep 23 06:39:53 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end processing, checked 5641 links at 1.9 links/s, slept 03:00:00
Sep 23 06:39:53 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin load workset
Sep 23 06:39:55 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end load workset, 14 owners (11 capped), 5831 links, 1071 unvisited links, 3327 good links (oldest=126d), 1433 bad links (oldest=2d)
Sep 23 06:39:55 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin processing
Sep 23 07:29:55 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end processing, checked 5472 links at 1.8 links/s, slept 03:00:00
Sep 23 07:29:55 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin load workset
Sep 23 07:29:57 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: end load workset, 14 owners (11 capped), 5588 links, 1269 unvisited links, 3086 good links (oldest=126d), 1233 bad links (oldest=2d)
Sep 23 07:29:57 uc3-ezidui-prd01 ezid-proc-errorlog[775539]:    INFO ezidapp.management.commands.proc-link-checker 140184061902848: begin processing