Too slow on large real world codebases

[oblitum]

Consider the following trivial c++ program:

Case 1

#include <iostream>
#include <boost/bimap.hpp>

struct S { int x; };

int main() {
    using namespace std;
    using namespace boost;

    S s;
    s.x;
}

Automatic semantic completion just after the member access operator will work, but forced semantic completion just before it will not. This happens because YCM is unable to handle large numbers of identifiers.

Forced semantic completion before . makes libclang return global scope completion data. libclang is very fast in doing so, YCM chokes. Two alternatives can happen:

• It will always timeout [fixed by #2657]
• Results come up, but are very slow

Things that always happen:

• High CPU consumption
• Typing lag (Vim hangs) [fixed by #2657]

Completion at global scope is a very important use case, specially in C codebases where nearly everything lives at the global scope. For example:

Case 2

#include <windows.h>

struct S { int x; };

int main() {
    S s;
    s.x;
}

It's a very common use case to wish to have completion for the Windows API, which is all C functions. In this realm the most useful and expected thing that YCM could offer is completion of the API provided by the included header: it simply can't handle it, despite how ubiquitous windows.h is.

Program 1 below was used to verify bare libclang timings for these usecases (with LIBCLANG_TIMING=1 the timings can be compared with the internal libclang timings).

For case 1 after . (#define flags linux_flags):

❯❯❯ ./libclang-timing case1.cpp 11 7
>>> First run: 5 results in 4ms
>>> Second run: 5 results in 3ms

>>> AFTER REPARSE

>>> Third run: 5 results in 3ms
>>> Fourth run: 5 results in 3ms

For case 1 before . (#define flags linux_flags):

❯❯❯ ./libclang-timing case1.cpp 11 6
>>> First run: 12989 results in 57ms
>>> Second run: 12989 results in 59ms

>>> AFTER REPARSE

>>> Third run: 13123 results in 39ms
>>> Fourth run: 13123 results in 37ms

For case 2 after . (#define flags windows_flags):

❯❯❯ ./libclang-timing case2.cpp 7 7
>>> First run: 5 results in 1ms
>>> Second run: 5 results in 1ms

>>> AFTER REPARSE

>>> Third run: 5 results in 1ms
>>> Fourth run: 5 results in 1ms

For case 2 before . (#define flags windows_flags):

❯❯❯ ./libclang-timing case2.cpp 7 6
>>> First run: 43304 results in 106ms
>>> Second run: 43304 results in 99ms

>>> AFTER REPARSE

>>> Third run: 43340 results in 3ms
>>> Fourth run: 43340 results in 3ms

Notice that reparsing has been added as I suspect my experience apparently conflicts with this comment:

  // codeCompleteAt reparses the TU if the underlying source file has changed on
  // disk since the last time the TU was updated and there are no unsaved files.
  // If there are unsaved files, then codeCompleteAt will parse the in-memory
  // file contents we are giving it. In short, it is NEVER a good idea to call
  // clang_reparseTranslationUnit right before a call to clang_codeCompleteAt.
  // This only makes clang reparse the whole file TWICE, which has a huge impact
  // on latency. At the time of writing, it seems that most users of libclang
  // in the open-source world don't realize this (I checked). Some don't even
  // call reparse*, but parse* which is even less efficient.

Despite that, ~100ms is reasonably unnoticeable (but alarming compared to ~3ms), it's not libclang's fault. The windows.h use case can be verified from Linux if the tips in this blog post are followed.

It's around ~35k identifiers that YCM starts to choke a lot.

I've experienced YCM slowness before on huge files, and I generally just use vim -u NONE for opening huge files to avoid that. Files that have no semantic completion at all, just identifier completion, like some .sql file.

With this information in mind, I've created Program 2 to generate output with 60k identifiers. Saving this output to identifiers.sql and opening it with YCM, trying to edit at the end of the file the same problems will happen without any semantic completion:

• If aaa is typed, YCM will simply timeout [fixed by #2657]
• If aaaaaa is typed, YCM may be able to complete, but it'll be slow.
• if backspace is used to delete chars, Vim hangs. Editing in general is slow [fixed by #2657]. CPU consumption is high.

Video demonstration:

• https://vimeo.com/219545420

System information:

• Intel® Core™ i7-7700K Processor
• DDR4 Corsair Vengeance LPX 16GB 2400MHz RAM
• ArchLinux Operating System
• gcc 7.1.1
• libc++ 4.0.0
• Boost 1.64
• Enterprise WDK 1703
• NeoVim 0.2.0

Related issue:

• https://github.com/Valloric/YouCompleteMe/issues/777#issuecomment-236626561

---

Program 1

#include <chrono>
#include <cstdlib>
#include <iostream>

#include <clang-c/Index.h>

// Compile with:
// g++ -O3 libclang-timing.cpp -o libclang-timing -lclang
// Run with:
// LIBCLANG_TIMING=1 ./libclang-timing file.cpp line column

const char *linux_flags[] = {
    "-x",
    "c++",
    "-pedantic",
    "-std=c++1z",
    "-stdlib=libc++",
    "-isystem",
    "/usr/include/c++/v1",
    "-Wall",
    "-Wextra",
    "-isystem",
    "/usr/local/include",
    "-isystem",
    "/usr/lib/clang/4.0.0/include",
    "-isystem",
    "/usr/include",
};

const char *windows_flags[] = {
    "-x",
    "c++",
    "--target=i386-pc-windows-msvc",
    "-ferror-limit=64",
    "-fms-compatibility-version=19",
    "-Wall",
    "-Wextra",
    "-Wno-unknown-pragmas",
    "-U__clang__",
    "-U__clang_version__",
    "-U__clang_major__",
    "-U__clang_minor__",
    "-U__clang_patchlevel__",
    "-DWIN32",
    "-D_WINDOWS",
    "-DNDEBUG",
    "-D_MT",
    "-D_X86_=1",
    "-DNOMINMAX",
    "-D_WIN32_WINNT=0x0501",
    "-D_CRT_SECURE_NO_WARNINGS=1",
    "-nostdinc",
    "-isystem",
    "/mnt/wdk/1703/program files/windows kits/10/include/10.0.15063.0/shared",
    "-isystem",
    "/mnt/wdk/1703/program files/windows kits/10/include/10.0.15063.0/ucrt",
    "-isystem",
    "/mnt/wdk/1703/program files/windows kits/10/include/10.0.15063.0/um",
    "-isystem",
    "/mnt/wdk/1703/program files/microsoft visual studio 14.0/vc/include",
};

#define flags linux_flags

int main(int argc, const char *argv[]) {
    using std::cout;
    using std::cerr;
    using std::endl;
    using std::chrono::milliseconds;
    using std::chrono::duration_cast;
    using std::chrono::high_resolution_clock;

    if (argc != 4) {
        cout << argv[0] << " file.cpp line colum" << endl;
        return EXIT_FAILURE;
    }

    CXIndex index = clang_createIndex(0, 0);
    if (!index) {
        cerr << "createIndex failed" << endl;
        return EXIT_FAILURE;
    }

    CXTranslationUnit tu;
    CXErrorCode result = clang_parseTranslationUnit2FullArgv(
        index, argv[1], flags, sizeof(flags) / sizeof(flags[0]), nullptr, 0,
        CXTranslationUnit_DetailedPreprocessingRecord |
            CXTranslationUnit_Incomplete |
            CXTranslationUnit_IncludeBriefCommentsInCodeCompletion |
            CXTranslationUnit_CreatePreambleOnFirstParse |
            CXTranslationUnit_KeepGoing |
            clang_defaultEditingTranslationUnitOptions(),
        &tu);

    if (result != CXError_Success) {
        cerr << "clang_parseTranslationUnit2FullArgv failed" << endl;
        return EXIT_FAILURE;
    }

    const unsigned int line   = strtoul(argv[2], 0, 10);
    const unsigned int column = strtoul(argv[3], 0, 10);

    auto start = high_resolution_clock::now();
    CXCodeCompleteResults *completion_results =
        clang_codeCompleteAt(tu, argv[1], line, column, nullptr, 0,
                             clang_defaultCodeCompleteOptions() |
                                 CXCodeComplete_IncludeBriefComments);
    auto elapsed = high_resolution_clock::now() - start;

    if (!completion_results) {
        cerr << "Could not complete" << endl;
        return EXIT_FAILURE;
    }

    cout << ">>> First run: " << completion_results->NumResults
         << " results in " << duration_cast<milliseconds>(elapsed).count()
         << "ms" << endl;

    clang_disposeCodeCompleteResults(completion_results);

    start = high_resolution_clock::now();
    completion_results =
        clang_codeCompleteAt(tu, argv[1], line, column, nullptr, 0,
                             clang_defaultCodeCompleteOptions() |
                                 CXCodeComplete_IncludeBriefComments);
    elapsed = high_resolution_clock::now() - start;

    if (!completion_results) {
        cerr << "Could not complete" << endl;
        return EXIT_FAILURE;
    }

    cout << ">>> Second run: " << completion_results->NumResults
         << " results in " << duration_cast<milliseconds>(elapsed).count()
         << "ms" << endl;

    clang_disposeCodeCompleteResults(completion_results);

    clang_reparseTranslationUnit(tu, 0, nullptr,
                                 clang_defaultReparseOptions(tu));

    cout << "\n>>> AFTER REPARSE\n" << endl;

    start = high_resolution_clock::now();
    completion_results =
        clang_codeCompleteAt(tu, argv[1], line, column, nullptr, 0,
                             clang_defaultCodeCompleteOptions() |
                                 CXCodeComplete_IncludeBriefComments);
    elapsed = high_resolution_clock::now() - start;

    if (!completion_results) {
        cerr << "Could not complete" << endl;
        return EXIT_FAILURE;
    }

    cout << ">>> Third run: " << completion_results->NumResults
         << " results in " << duration_cast<milliseconds>(elapsed).count()
         << "ms" << endl;

    clang_disposeCodeCompleteResults(completion_results);

    start = high_resolution_clock::now();
    completion_results =
        clang_codeCompleteAt(tu, argv[1], line, column, nullptr, 0,
                             clang_defaultCodeCompleteOptions() |
                                 CXCodeComplete_IncludeBriefComments);
    elapsed = high_resolution_clock::now() - start;

    if (!completion_results) {
        cerr << "Could not complete" << endl;
        return EXIT_FAILURE;
    }

    cout << ">>> Fourth run: " << completion_results->NumResults
         << " results in " << duration_cast<milliseconds>(elapsed).count()
         << "ms" << endl;

    for (unsigned int i = 0;
         i < clang_codeCompleteGetNumDiagnostics(completion_results); i++) {
        const CXDiagnostic &diagnostic =
            clang_codeCompleteGetDiagnostic(completion_results, i);
        const CXString &s = clang_getDiagnosticSpelling(diagnostic);
        cout << clang_getCString(s) << endl;
    }

    clang_disposeCodeCompleteResults(completion_results);
}

---

Program 2

#include <cstdio>
#include <algorithm>

int main() {
    using namespace std;

    char identifier[6] = {};

    int count = 0;
    for (int i = 0; i < 6250; ++i) {
        for (int j = 0; j < 8; ++j) {
            sprintf(identifier, "%05d", count);
            for (char &c : identifier)
                c = c ? c - '0' + 'a' : c;
            printf("a_a_a_%s ", identifier);
            ++count;
        }
        printf("\n");
    }
}

[bstaletic]

I gave this a very quick test with my YCM including changes from #2657. It works much faster than before those changes, so could you give that PR a try? The PR is implementing async semantic completion.

[oblitum]

Hi @bstaletic. Did you give it a test on case 1, case 2 or program output of Program 2?

[bstaletic]

I tried it on all three of those, but I couldn't get Program 1 to work as I don't have Windows installed at all.

[oblitum]

I didn't try #2657 yet, but I did check it before opening this issue. I'll try it but due to the scope of the pull, I was suspecting it wouldn't touch possibly existing issues in the request/display process as a whole.

Notice that Program 1 was compiled and tested on Linux. I didn't use Windows for anything. Also notice that some flags in it may require changes for your machine, like header locations, etc. They're based on .ycm_extra_conf.py flags.

[bstaletic]

Actually, my bad. I have not used anything that contains <windows.h>, which means I tested Case 1 and Program 2.

As for Program 1, I managed to get it to work. Completions are not instantanious, but are far from being slow.

[oblitum]

@bstaletic my bad, I've updated the issue. I've posted the wrong case 1 snippet, it was to be based on https://github.com/Valloric/YouCompleteMe/issues/777#issuecomment-236626561 but I ended up removing the using namespaces. Unsure whether it will make any difference for you it just gets a bit slower on my side on original YCM. The windows.h case is more problematic.

[bstaletic]

Still, I don't seealmost any slow down with the using namespace case. I think you should try #2657 and report back. The PR won't be merged until the end of the week.

[oblitum]

@bstaletic I've tried #2657. Overall completion is much improved, kudos to @micbou! Still it's behaving as I was expecting.

What it does:

• No more timeouts, great!
• Stops making Vim hang while typing!

What it doesn't do:

• Completion arrives, but late. The slowness in the "request/display process as a whole" isn't solved, which is understandable since this issue isn't a target of that pull request, this is masqueraded by the new async menu refreshing mechanism.
• Lower CPU consumption.

[bstaletic]

@oblitum Your observations seem resonable, but, on my laptop, I just can't agree with "Completion arrives, but late". The initial parse and completions too about two seconds, but to make it that slow I had to use echo 3 | tee /proc/sys/vm/drop_caches. In any other case the completions were almost instant.

That said, I do believe you it can still feel slow for you (and others). But frankly, I have no idea where would I start looking to find the source of the slowness.

As for being resource exensive, Program 1 took ~70MiB at most. I didn't feel any CPU hogging. Those results are right after dropping caches.

[oblitum]

@bstaletic Here a video demonstrating it: https://vimeo.com/219545420. I've updated Program 2 to 60k identifiers (doubling the original) to make the effect clearly visible. On case 2, the bare inclusion of windows.h will generate around 43k identifiers, the effect can still be felt.

It's also worth noticing that #2657 introduces a new semantic completion behavior: after forced semantic completion, if I backspace to erase some chars of the current incomplete identifier, I'm forced to force semantic completion again to get the original semantic identifier ordering. I ignore the extension of the effects of this but some people may not like.

I'm on a 7700K PC.

---

Sorry about the second part of the video for the case 2, you'll be unable to know when I hit ctrl-space, I have no keyboard screencast software at the moment, I'll think of doing an update on that later.

[bstaletic]

I knew there was something wrong when I read about your CPU. I'm on an i7 3610QM, so I definitely have less raw power than you. The thing that was wrong about my results was that I was looking at completions in the code that generates the large number of completions.

Unlike you, I'm still hitting a timeout unless I type five character in the generated file.

As for case 1, I can't actually say it's too fast, but considering how big the boost's bimap is, I'm not too surprised.

[oblitum]

Ah OK, you were testing the program, not the output. I hope others don't fall in the same trap :)

[bstaletic]

I noticed one more thing.

It's also worth noticing that #2657 introduces a new semantic completion behavior, after forced semantic completion, if I backspace to erase some chars of the current incomplete identifier, I'm forced to force semantic completion again to get the original semantic identifier ordering. I ignore the extension of the effects of this but some people may not like.

This doesn''t happen with low number of identifiers. Also, I had to hit <C-Space> after reinserting, not after deleting.

[micbou]

PR https://github.com/Valloric/ycmd/pull/774 should improve responsiveness and reduce CPU usage in Case 1 and Case 2.

[oblitum]

PR Valloric/ycmd#774 should improve responsiveness and reduce CPU usage in Case 1 and Case 2.

Confirmed! It's much improved.

[oblitum]

@micbou IMO, it got so much more usable now, thanks. Your changes improved a lot on the semantic results, but I'm also with others applied, #2657 and this local one:

diff --git a/cpp/ycm/IdentifierDatabase.cpp b/cpp/ycm/IdentifierDatabase.cpp
index 4a44bc7b..5e4e349a 100644
--- a/cpp/ycm/IdentifierDatabase.cpp
diff --git a/cpp/ycm/IdentifierDatabase.cpp b/cpp/ycm/IdentifierDatabase.cpp
index 4a44bc7b..5e4e349a 100644
--- a/cpp/ycm/IdentifierDatabase.cpp
+++ b/cpp/ycm/IdentifierDatabase.cpp
@@ -111,7 +111,10 @@ void IdentifierDatabase::ResultsForQueryAndType(
     }
   }

-  std::sort( results.begin(), results.end() );
+  if (results.size() < 50)
+    std::sort( results.begin(), results.end() );
+  else
+    std::partial_sort( results.begin(), results.begin() + 50, results.end() );
 }

diff --git a/cpp/ycm/PythonSupport.cpp b/cpp/ycm/PythonSupport.cpp
index 3f2d3f1d..0da9334d 100644
--- a/cpp/ycm/PythonSupport.cpp
+++ b/cpp/ycm/PythonSupport.cpp
@@ -101,11 +101,16 @@ boost::python::list FilterAndSortCandidates(
       }
     }

-    std::sort( result_and_objects.begin(), result_and_objects.end() );
+    if (result_and_objects.size() < 50)
+      std::sort( result_and_objects.begin(), result_and_objects.end() );
+    else
+      std::partial_sort( result_and_objects.begin(),
+                         result_and_objects.begin() + 50,
+                         result_and_objects.end() );
   }

-  for ( const ResultAnd< int > &result_and_object : result_and_objects ) {
-    filtered_candidates.append( candidates[ result_and_object.extra_object_ ] );
+  for ( size_t i = 0; i < result_and_objects.size() && i < 50; ++i ) {
+    filtered_candidates.append( candidates[ result_and_objects[i].extra_object_ ] );

[oblitum]

@micbou I've noticed a large improvement on the case for Program 2 output due to the previous patch, before applying Valloric/ycmd#774.

[oblitum]

Folks, feel free to close this if it reaches a good enough state. I've been stuck with the improvements due to my previous patch but couldn't move further on my fork due to conflicting changes with #2657 regarding parameter hints. As far as I've tested up to my previous patch I was satisfied enough already, despite not leveraging the new async system.

[oblitum]

No time for looking into Vim completion at the moment at all.

[vheon]

@oblitum just to let you know we've implemented partial sorting in ycmd ;)

[oblitum]

@vheon that's great!

[micbou]

Completing at global scope is now almost instant in cases 1 and 2 so we can definitely close this.