Investigate ~1.5x increase in Duration for N=11 graphs across all graph algorithms

[wbkboyer]

Problem statement

After merging #108 and #109 , which included the regenerated test tables up to N=10, I ran planarity_testAllGraphs_orchestrator.py and test_table_generator.py to see how the number of OKs vs. NONEMBEDDABLEs had changed for N=11, since the last time the tables were updated was with #66 and therefore didn't reflect the results of the fix from #106. After having done so (twice, the second time after a fresh reboot), I observed that the Duration had increased significantly for all graph algorithms:

Algorithm	Old Duration	New Duration
p	4107.813	6594.341
d	2898.858	4906.0
o	3705.56	5877.968
2	3842.266	5845.16
3	6418.503	9419.278
4	4272.314	6271.875

I re-ran N=10 under the same conditions and did not observe this duration bloat:

Algorithm	Old Duration	New Duration
p	72.285	83.655
d	65.857	58.971
o	67.441	64.593
2	70.315	66.251
3	106.624	99.173
4	59.065	56.752

Investigation steps

• Create script to duplicate every graph in each .g6 file in a directory (i.e. the output of graph_generation_orchestrator.py for a given order)
  • N.B. I observed that the size difference of the "fat middle" of graphs for N=11 vs. N=10 was ~92x, so I chose that as the default duplication factor
• Re-run planarity_testAllGraphs_orchestrator.py and test_table_generator.py on these expanded .g6 input files for N=10 with the planarity executable compiled from the source as of Issue 65 - Test Table Generator script #66 vs. the current HEAD
• Re-run planarity_testAllGraphs_orchestrator.py and test_table_generator.py on the .g6 input files for N=11 with the planarity executable compiled from the source as of Issue 65 - Test Table Generator script #66 vs. Issue 64 and Issue 67 - EnsureArcCapacity() before attaching -(d34) algorithm extensions in SpecificGraph() and testAllGraphs() #68 vs. the current HEAD
• Compile the planarity executable corresponding to the code as of Issue 65 - Test Table Generator script #66 using the MSVC cl compiler toolchain and re-run N=11 to see the speed differences between the results obtained using MinGW-32 gcc
• Compile the planarity executable corresponding to the code as of Issue 64 and Issue 67 - EnsureArcCapacity() before attaching -(d34) algorithm extensions in SpecificGraph() and testAllGraphs() #68 using the MSVC cl compiler toolchain and re-run N=11 to see the speed differences between the results obtained using MinGW-32 gcc
• Compile the planarity executable corresponding to the code at HEAD of master using the MSVC cl compiler toolchain and re-run N=11 to see the speed differences between the results obtained using MinGW-32 gcc
• Compile the planarity executable corresponding to the code at HEAD of master using clang and run N=11 on the MacBook Pro to compare against the original table Durations

[wbkboyer]

After generating .g6 files for N=10 that had a duplication factor of 92 to make the size of the files roughly equivalent to those of N=11 (turned out to be a couple more graphs, actually), I re-ran planarity_testAllGraphs_orchestrator.py and regenerated the tables using test_table_generator.py to obtain the following results for the executable compiled from the HEAD of master (see middle column in particular)

Algorithm	Duration (12005168 for N=10)	Duration (1104475456 for expanded N=10)	Duration (1018997864 for N=11)
p	83.655	6901.951	6594.341
d	58.971	4622.437	4906.0
o	64.593	4841.362	5877.968
2	66.251	4952.594	5845.16
3	99.173	7457.797	9419.278
4	56.752	4241.012	6271.875

@john-boyer-phd observed that if you look at the ratios of the max edge-count from N=10 vs. N = 11, $\frac{50}{55} \approx 0.91$, is "in the same neck of the woods" as the ratio of the time taken for the expanded N=10 .g6 files vs. N=11 files, e.g. $\frac{7457}{9419} \approx 0.79$ for p, so this might be more to do with the way C handles the FILE * (see #55 for some related background info).

---

I compiled the planarity executable from source circa #66 and ran python_testAllGraphs_orchestrator.py on the expanded N=10 .g6 files; however, upon running the test_table_generator.py to compile the planarity output files into a table, I noticed that for (d, 3, 4) I was getting ERROR for M=31 and above; this made me remember #64 and how before the fix, the dynamic storage growth would fail if we'd already attached those three graph algorithm extensions for $M \geq 3N + 1. However, since M=31,45 contributes < 15min to the durations for the head revision of the executable, and since the executable from #66 has similar timing for the other edge-counts, it's probably safe to say that if those edge-counts hadn't errored out, they'd have a similar duration to the executable compiled from the HEAD of master.

Algorithm	HEAD Duration (expanded N=10)	#66 Duration (expanded N=10)	HEAD Duration (N=11)
p	6901.951	7153.653	6594.341
d	4622.437	4372.24	4906.0
o	4841.362	4835.156	5877.968
2	4952.594	4960.107	5845.16
3	7457.797	7259.763	9419.278
4	4241.012	4033.127	6271.875

---

Looking at the above table and having the realization about how this might be related to #68 (see #64 and #67), I wanted to look at the ratios of (p, o, 2) vs. (d, 3, 4) for N=11 from #66 , #68 , and HEAD of master, since this might hint that there's something funky with the dynamic memory allocation that only gets worse as N increases. Therefore, this might be related to #85.

I compiled the planarity executable from source circa #68 and ran planarity_testAllGraphs_orchestrator.py for N=11:

Algorithm	Original #66 Duration	#68 Duration	HEAD Duration
p	4107.813	6465.153	6594.341
d	2898.858	4880.452	4906.0
o	3705.56	5807.815	5877.968
2	3842.266	5775.356	5845.16
3	6418.503	9421.973	9419.278
4	4272.314	6234.082	6271.875

The ratio of total Duration going from #66 to #68 per algorithm:

Algorithm	Ratio
p	1.57
d	1.68
o	1.57
2	1.50
3	1.47
4	1.46

This seems strange, as the changes of #68 only should have impacted (d, 3, 4) (i.e. only gp_EnsureArcCapacity() to N * (N - 1) up front when the chosen command specifier was (d, 3, 4) before we AttachAlgorithm() to the current graph and its copy (used for checking embed integrity)), but the ratio increased across the board...

---

I'm re-running planarity_testAllGraphs_orchestrator.py for N=11 with the freshly-compiled #66 executable to double-check the results from those original tables at the present date, since it still could be a hardware (HDD failure?? Issues with file pointers (see #55)??), compiler issue (in #58, I added the -O3 flag to all Release configurations in tasks.json, in accordance with my research in this comment on #54; however, this happened before the tables committed in #66 were generated, and I haven't updated my MinGW gcc compiler toolchain since initially setting up my development environment. The only other thing I can think is that maybe I was using the executable compiled with MSVC cl when generating the tables committed in #66 ???), or possibly (but extremely unlikely) some change that I've made to the planarity_testAllGraphs_orchestrator.py since those initial tables (commit history here).

[wbkboyer]

I'm having a hard time grokking what's going on here: I now have the results from running the planarity executable compiled from head as of #66 and #68 both with MinGW32 gcc and MSVC cl, and I can't reproduce the Duration results that were committed as of #66.

Algorithm	Original #66	New MinGW32 #66	New MSVC #66	New MinGW32 #68	New MSVC #68	Current HEAD of master (first run)	Current HEAD of master (second run)	Current HEAD of master (third run)
p	4107.813	6257.184	5734.218	6465.153	6561.775	6523.076	6526.764	6594.341
d	2898.858	4400.936	3733.041	4880.452	4821.187	4869.514	4924.423	4906.0
o	3705.56	5710.607	5287.164	5807.815	5922.17	5856.877	5853.688	5877.968
2	3842.266	5646.926	5409.423	5775.356	5846.997	5826.236	5864.013	5845.16
3	6418.503	8689.063	8477.265	9421.973	9438.308	9401.905	9484.017	9419.278
4	4272.314	5690.06	5545.707	6234.082	6232.65	6268.564	6264.924	6271.875

Some additional investigation into possible causes:

1. I noticed that the filenames for the original tables committed in Issue 65 - Test Table Generator script #66 were of the old format, and also noticed that the new N=11 files were generated after Issue 65 - Test Table Generator script #66 was merged. I have checked and I don't have copies of those test.n{N}.m{M}.g6 files on other devices (i.e. I am positive I had run planarity on my Windows machine using .g6 files stored on my HDD; this comment substantiates they were not produced on my MacBook Pro). However, even though I have run the current tests on .g6 files generated after Issue 65 - Test Table Generator script #66 was merged, since the geng.exe compilation timestamp is from 2024/01/11, I have to assume that the .g6 files are the same as those originally used.
2. I am using the most recent versions of the TestSupport scripts, rather than the versions used at the time of the original table creation. However, looking at the file history for planarity_testAllGraphs_orchestrator.py and test_table_generator.py, I can see no reason why the modern scripts would influence the results of planarity's testAllGraphs()
3. Comparing the read/write speeds for my HDD against this comment using winsat disk -drive E: determined:
   • Random 16.0 read - 1.45 MB/s is now 1.44 MB/s
   • Sequential 64.0 read - 163.95 MB/s is now 163.97 MB/s
     So I genuinely don't think there's HDD failure causing a dip in file read speed impacting the total Duration.

[wbkboyer]

Another hypothesis is that the test tables committed during #66 were produced by my Macbook; as a preliminary test, I compiled the planarity executable from HEAD of master on my MacBook Pro (see this comment on #54 for specs) using clang to see if the Durations for all graph algorithm commands corresponded to the original.

Algorithm	Tables submitted in #66	HEAD of master on Mac (clang)	HEAD of master on Windows (MinGW gcc)
p	4107.813	2232.424	6594.341
d	2898.858	1372.64	4906.0
o	3705.56	1921.814	5877.968
2	3842.266	1966.019	5845.16
3	6418.503	3481.032	9419.278
4	4272.314	2259.865	6271.875

Since these results are almost twice as fast than those committed during #66, it seems unlikely that I erroneously committed tables produced by running an executable compiled with a different compiler toolchain (clang vs. MinGW gcc) and run on a different machine (MacBook Pro vs. Windows 10), so this doesn't explain the discrepancy 😢

---

Another hypothesis was that the .g6 files were on my Windows machine's SSD rather than HDD; however, re-running #66 with the DEFAULT_EDGE_LIMIT set to 6; however, the timing data doesn't support this hypothesis.

Algorithm	Tables submitted in #66	New executable compiled from #66 with DEFAULT_EDGE_LIMIT set to 6 running on .g6 files stored on SSD
p	4107.813	5995.516
d	2898.858	4382.06
o	3705.56	5335.903
2	3842.266	5530.734
3	6418.503	9449.043
4	4272.314	6151.926

[wbkboyer]

TL;DR I don't believe this slowdown is as a result of any code changes that have occurred since the first table for N=11 was committed with #66, but I am unable to determine if other system-level changes are the root cause.

---

I wanted to determine what Windows updates had been installed in the intervening months since the table was generated, so I ran the wmic command:

wmic qfe where "InstalledOn like '%/%/2024'" list full > WindowsUpdateHistory.txt

To produce
WindowsUpdateHistory.txt

• https://support.microsoft.com/en-us/topic/november-12-2024-kb5045933-cumulative-update-for-net-framework-3-5-and-4-8-1-for-windows-10-version-21h2-and-windows-10-version-22h2-d2bb4032-865b-40eb-be0d-ac1bbf240125
• https://support.microsoft.com/en-us/topic/november-12-2024-kb5046613-os-builds-19044-5131-and-19045-5131-44e6c27e-e188-4dd5-8ad2-edde2e235c01
• https://support.microsoft.com/en-us/topic/march-22-2024-kb5037422-os-build-20348-2342-out-of-band-e8f5bf56-c7cb-4051-bd5c-cc35963b18f3
• https://support.microsoft.com/en-us/topic/may-29-2024-kb5037849-os-build-19045-4474-preview-cda7ed71-6202-45ed-a649-63b11fedabfe
• https://support.microsoft.com/en-us/topic/july-9-2024-kb5040427-os-builds-19044-4651-and-19045-4651-78458e76-9404-41b4-91b2-6d3cdcf4a530
• https://support.microsoft.com/en-us/topic/august-13-2024-kb5041580-os-builds-19044-4780-and-19045-4780-2ef55b0d-bb01-41c8-8629-4146929792ad
• https://support.microsoft.com/en-us/topic/september-10-2024-kb5043064-os-builds-19044-4894-and-19045-4894-cd14b547-a3f0-4b8f-b037-4ae3ce83a781
• https://support.microsoft.com/en-us/topic/september-24-2024-kb5043131-os-build-19045-4957-preview-2d4a5c54-ac58-4bdb-8685-57d578650e5f

A cursory look seems to indicate that none of these updates should have caused a system-wide slowdown, but more thorough examination would be required to entirely rule it out.

---

The only other thing that's changed has been the VSCode C/C++ extension version, from v.1.19.3 to v1.22.11 at present.

This could be an issue with Windows antivirus suddenly acting up when I run any planarity executable, but there have been no warnings (the only time I experienced this was in February on #16 when executables compiled with MSVC cl were flagged as Trojan:Win32/Wacatac.C!ml). I even checked the Event Viewer logs under Event Viewer >> Applications and Services Logs >> Microsoft >> Windows >> Windows Defender >> Operational, but see nothing out of the ordinary.

[john-boyer-phd]

Although we still don't know exactly what did cause the slowdown, relative to your run over 6 months ago, you have run sufficient tests to show that it is not due to any code changes made since then. Also, the "expanded" N=10 file showed that it's not something special that starts happening at N=11, but rather something that is happening due to reading a billion graphs from a file. This points to some kind of slowdown in large file disk operations on the given computer. Bottom line, it's not something that happened to the core algorithm implementations, which was the real concern, so I think you can close this (after checking off the remaining tasks, which you did perform).

[wbkboyer]

Rock on! 🚀