formattedMessage cache is obsolete when size > 100

[kevinramharak]

Looking into the performance problems I checked o see what happens when a file has more diagnostics than the cache size allows for (currently 100).

I found that the part:

pretty-ts-errors/src/extension.ts

Lines 61 to 64 in 2531440

	if (cache.size > 100) {
	const firstCacheKey = cache.keys().next().value;
	cache.delete(firstCacheKey);
	}

does not work as intended, since the first diagnostic that is being checked for will not be part of the cache. Then the newly formattedMessage will replace an entry in the cache, causing the next diagnostic to also be a cache miss.

Example file

const diagnostic_1 = a1;
const diagnostic_2 = a2;
const diagnostic_3 = a3;
const diagnostic_4 = a4;
const diagnostic_5 = a5;
const diagnostic_6 = a6;
const diagnostic_7 = a7;
const diagnostic_8 = a8;
const diagnostic_9 = a9;
const diagnostic_10 = a10;
const diagnostic_11 = a11;
const diagnostic_12 = a12;
const diagnostic_13 = a13;
const diagnostic_14 = a14;
const diagnostic_15 = a15;
const diagnostic_16 = a16;
const diagnostic_17 = a17;
const diagnostic_18 = a18;
const diagnostic_19 = a19;
const diagnostic_20 = a20;
const diagnostic_21 = a21;
const diagnostic_22 = a22;
const diagnostic_23 = a23;
const diagnostic_24 = a24;
const diagnostic_25 = a25;
const diagnostic_26 = a26;
const diagnostic_27 = a27;
const diagnostic_28 = a28;
const diagnostic_29 = a29;
const diagnostic_30 = a30;
const diagnostic_31 = a31;
const diagnostic_32 = a32;
const diagnostic_33 = a33;
const diagnostic_34 = a34;
const diagnostic_35 = a35;
const diagnostic_36 = a36;
const diagnostic_37 = a37;
const diagnostic_38 = a38;
const diagnostic_39 = a39;
const diagnostic_40 = a40;
const diagnostic_41 = a41;
const diagnostic_42 = a42;
const diagnostic_43 = a43;
const diagnostic_44 = a44;
const diagnostic_45 = a45;
const diagnostic_46 = a46;
const diagnostic_47 = a47;
const diagnostic_48 = a48;
const diagnostic_49 = a49;
const diagnostic_50 = a50;
const diagnostic_51 = a51;
const diagnostic_52 = a52;
const diagnostic_53 = a53;
const diagnostic_54 = a54;
const diagnostic_55 = a55;
const diagnostic_56 = a56;
const diagnostic_57 = a57;
const diagnostic_58 = a58;
const diagnostic_59 = a59;
const diagnostic_60 = a60;
const diagnostic_61 = a61;
const diagnostic_62 = a62;
const diagnostic_63 = a63;
const diagnostic_64 = a64;
const diagnostic_65 = a65;
const diagnostic_66 = a66;
const diagnostic_67 = a67;
const diagnostic_68 = a68;
const diagnostic_69 = a69;
const diagnostic_70 = a70;
const diagnostic_71 = a71;
const diagnostic_72 = a72;
const diagnostic_73 = a73;
const diagnostic_74 = a74;
const diagnostic_75 = a75;
const diagnostic_76 = a76;
const diagnostic_77 = a77;
const diagnostic_78 = a78;
const diagnostic_79 = a79;
const diagnostic_80 = a80;
const diagnostic_81 = a81;
const diagnostic_82 = a82;
const diagnostic_83 = a83;
const diagnostic_84 = a84;
const diagnostic_85 = a85;
const diagnostic_86 = a86;
const diagnostic_87 = a87;
const diagnostic_88 = a88;
const diagnostic_89 = a89;
const diagnostic_90 = a90;
const diagnostic_91 = a91;
const diagnostic_92 = a92;
const diagnostic_93 = a93;
const diagnostic_94 = a94;
const diagnostic_95 = a95;
const diagnostic_96 = a96;
const diagnostic_97 = a97;
const diagnostic_98 = a98;
const diagnostic_99 = a99;
const diagnostic_100 = a100;
const diagnostic_101 = a101;
const diagnostic_102 = a102;
const diagnostic_103 = a103;

I doubt this is the cause of the performance issue, but it is definitely not helping. I wonder how much the cache actually helps at all, as far as I can tell the formatting is not expensive so far.

[kevinramharak]

I looked into it a bit more, the cache does help a lot:

[3:41:59 PM] Diagnostics took 1254ms
[3:42:06 PM] Diagnostics took 736ms
[3:42:13 PM] Diagnostics took 315ms
[3:42:20 PM] Diagnostics took 0ms
[3:42:22 PM] Diagnostics took 0ms
[3:42:28 PM] Diagnostics took 1ms
[3:42:30 PM] Diagnostics took 2ms
[3:42:34 PM] Diagnostics took 198ms
[3:42:44 PM] Diagnostics took 188ms
[3:42:53 PM] Diagnostics took 254ms
[3:42:54 PM] Diagnostics took 190ms
[3:42:34 PM] Diagnostics took 198ms
[3:42:44 PM] Diagnostics took 188ms
[3:42:53 PM] Diagnostics took 254ms
[3:42:54 PM] Diagnostics took 190ms
[3:51:35 PM] Diagnostics took 220ms
[3:51:39 PM] Diagnostics took 227ms
[3:51:46 PM] Diagnostics took 161ms
[3:51:57 PM] Diagnostics took 220ms
[3:52:00 PM] Diagnostics took 29ms
[3:52:03 PM] Diagnostics took 1ms

The 2 initial logs are during startup. When the cache is hit it takes almost no time. If all items get a miss the time it takes will be noticeable.

File used:

const diagnostic_1: 1 = 2
const diagnostic_2: 2 = 3
const diagnostic_3: 3 = 4
const diagnostic_4: 4 = 5
const diagnostic_5: 5 = 6
const diagnostic_6: 6 = 7
const diagnostic_7: 7 = 8
const diagnostic_8: 8 = 9
const diagnostic_9: 9 = 10
const diagnostic_10: 10 = 11
const diagnostic_11: 11 = 12
const diagnostic_12: 12 = 13
const diagnostic_13: 13 = 14
const diagnostic_14: 14 = 15
const diagnostic_15: 15 = 16
const diagnostic_16: 16 = 17
const diagnostic_17: 17 = 18
const diagnostic_18: 18 = 19
const diagnostic_19: 19 = 20
const diagnostic_20: 20 = 21
const diagnostic_21: 21 = 22
const diagnostic_22: 22 = 23
const diagnostic_23: 23 = 24
const diagnostic_24: 24 = 25
const diagnostic_25: 25 = 26
const diagnostic_26: 26 = 27
const diagnostic_27: 27 = 28
const diagnostic_28: 28 = 29
const diagnostic_29: 29 = 30
const diagnostic_30: 30 = 31
const diagnostic_31: 31 = 32
const diagnostic_32: 32 = 33
const diagnostic_33: 33 = 34
const diagnostic_34: 34 = 35
const diagnostic_35: 35 = 36
const diagnostic_36: 36 = 37
const diagnostic_37: 37 = 38
const diagnostic_38: 38 = 39
const diagnostic_39: 39 = 40
const diagnostic_40: 40 = 41
const diagnostic_41: 41 = 42
const diagnostic_42: 42 = 43
const diagnostic_43: 43 = 44
const diagnostic_44: 44 = 45
const diagnostic_45: 45 = 46
const diagnostic_46: 46 = 47
const diagnostic_47: 47 = 48
const diagnostic_48: 48 = 49
const diagnostic_49: 49 = 50
const diagnostic_50: 50 = 51
const diagnostic_51: 51 = 52
const diagnostic_52: 52 = 53
const diagnostic_53: 53 = 54
const diagnostic_54: 54 = 55
const diagnostic_55: 55 = 56
const diagnostic_56: 56 = 57
const diagnostic_57: 57 = 58
const diagnostic_58: 58 = 59
const diagnostic_59: 59 = 60
const diagnostic_60: 60 = 61
const diagnostic_61: 61 = 62
const diagnostic_62: 62 = 63
const diagnostic_63: 63 = 64
const diagnostic_64: 64 = 65
const diagnostic_65: 65 = 66
const diagnostic_66: 66 = 67
const diagnostic_67: 67 = 68
const diagnostic_68: 68 = 69
const diagnostic_69: 69 = 70
const diagnostic_70: 70 = 71
const diagnostic_71: 71 = 72
const diagnostic_72: 72 = 73
const diagnostic_73: 73 = 74
const diagnostic_74: 74 = 75
const diagnostic_75: 75 = 76
const diagnostic_76: 76 = 77
const diagnostic_77: 77 = 78
const diagnostic_78: 78 = 79
const diagnostic_79: 79 = 80
const diagnostic_80: 80 = 81
const diagnostic_81: 81 = 82
const diagnostic_82: 82 = 83
const diagnostic_83: 83 = 84
const diagnostic_84: 84 = 85
const diagnostic_85: 85 = 86
const diagnostic_86: 86 = 87
const diagnostic_87: 87 = 88
const diagnostic_88: 88 = 89
const diagnostic_89: 89 = 90
const diagnostic_90: 90 = 91
const diagnostic_91: 91 = 92
const diagnostic_92: 92 = 93
const diagnostic_93: 93 = 94
const diagnostic_94: 94 = 95
const diagnostic_95: 95 = 96
const diagnostic_96: 96 = 97
const diagnostic_97: 97 = 98
const diagnostic_98: 98 = 99
const diagnostic_99: 99 = 100
const diagnostic_100: 100 = 101
const diagnostic_101: 100 = 102

[yoavbls]

Do you think we need to make the cache bigger? or change how it's working?

[kevinramharak]

@yoavbls I think it needs to be changed to be smarter about cache hits and misses. Although we could also just increase the cache size and see if people with performance issues notice a change.
onDidChangeDiagnostics seems to fire at least twice on a single change, and even more often when renaming files or symbols. Simple tests with 4 files a rename could trigger 5-10 events with seemingly the same diagnostics. I have no idea why that happens. I can't find any issue on github or StackOverflow that reports having issues with that.
If the order of uri.forEach and diagnostic.forEach are the same for each of those events and the total size of those diagnostics exceeds the cache size, all of those events will perform as if there is no cache. for 5-10 events of 100+ diagnostics that could easily add up to a few seconds of total time.
But if and how the amount of diagnostics exceeds the cache size is not clear to me, it seems odd to have a project where you have 100+ diagnostics from the typescript compiler.