Преамбула


Программы на C и C++, как правило, проводят бо?льшую часть своей жизни внутри функции main() и функций, прямо или косвенно вызываемых из main(). Тем не менее, на самом деле выполнение программы начинается вовсе не с main(), а с некоторого кода из стандартной библиотеки, поставляемой вместе с компилятором. Таковой код, по идее, должен подготавливать окружение для других функций стандартной библиотеки, которые, возможно, позовёт main(), а также параметры самой main() (под Windows; Unix-системы имеют тенденцию передавать argc/argv/envp в подготовленном виде прямо при запуске процесса, но речь не о них). Симметрично, завершающий return в функции main() — вовсе не последняя инструкция программы, после него следует ещё немного кода из стандартной библиотеки.
В Visual Studio «настоящая» точка входа в программу называется mainCRTStartup. В комплекте с VS идут исходники стандартной библиотеки, в VS2015 определение mainCRTStartup находится в %PROGRAMFILES(X86)%\VC\crt\src\vcruntime\exe_main.cpp, но, впрочем, всю работу выполняет exe_common.inl рядом. Давайте туда посмотрим.
...
        // If this module has any thread-local destructors, register the
        // callback function with the Unified CRT to run on exit.
        _tls_callback_type const * const tls_dtor_callback = __scrt_get_dyn_tls_dtor_callback();
        if (*tls_dtor_callback != nullptr && __scrt_is_nonwritable_in_current_image(tls_dtor_callback))
        {
            _register_thread_local_exe_atexit_callback(*tls_dtor_callback);
        }

        __telemetry_main_invoke_trigger(nullptr);

        //
        // Initialization is complete; invoke main...
        //

        int const main_result = invoke_main();

        //
        // main has returned; exit somehow...
        //

        __telemetry_main_return_trigger(nullptr);

        if (!__scrt_is_managed_app())
            exit(main_result);

        if (!has_cctor)
            _cexit();

        // Finally, we terminate the CRT:
        __scrt_uninitialize_crt(true, false);
        return main_result;
...



Идём глубже


Опытные параноики, несомненно, уже обратили внимание на вызовы __telemetry_main_invoke_trigger и __telemetry_main_return_trigger. Попробуем найти их исходники… а фигушки. При попытке зайти внутрь этих функций отладчик VS сообщает «telemetry.cpp не найден» (значит, файл с исходниками, который MS «забыла» включить в поставку, называется telemetry.cpp. Логично) и предлагает либо указать путь вручную, либо перейти к дизассемблированному коду.
Внимательный поиск других функций из telemetry.cpp находит ещё пару функций __vcrt_initialize_telemetry_provider и __vcrt_uninitialize_telemetry_provider, вызываемых в ходе, соответственно, инициализации и завершения.

Конечно, непредоставление исходников ещё не означает невозможности заглянуть внутрь. Разглядывание дизассемблированного кода приводит к переменной _Microsoft_CRTProvider типа const __vcrt_trace_logging_provider::_TlgProvider_t* const, а тип _TlgProvider_t уже не секретный и легко находится в SDK: %PROGRAMFILES(X86)%\Windows Kits\10\Include\10.0.10586.0\shared\TraceLoggingProvider.hа вот и документация. (В документации написано «Windows 10», что, впрочем, совершенно не мешает коду работать под Windows 7.) Так, хорошо, а куда оно пишет все эти логи?
TraceLogging events are sent to ETW as described in this section.
То есть это очередная инкарнация подсистемы Event Tracing for Windows. Ага.
Краткая справка для тех, кто впервые слышит аббревиатуру ETW: это инфраструктура для унифицированной обработки всевозможных логов и счётчиков, появившаяся ещё в Windows 2000 и получившая серьёзную прибавку в Vista. Желающие могут набрать в командной строке logman query providers для оценки масштаба.

Смотрим логи


Возьмём какую-нибудь простенькую программу, например:
#include <stdio.h>
int main()
{
	printf("Hello, World!\n");
	return 0;
}

Результат компиляции командой cl /Os hello.c: yadi.sk/d/pa0S5qVoqw9Q4
Итак, в скомпилированном exe-шнике должна быть запись каких-то логов перед и после вызова main(). Подсистема ETW просто отбрасывает всё, для чего не было команды на ведение логов. Давайте включим логи: именем администратора,
logman create trace test_crt_telemetry -p {5EEC90AB-C022-44B2-A5DD-FD716A222A15} -o C:\temp\test_telemetry
logman start test_crt_telemetry

(logman и нужная далее tracerpt — стандартные утилиты из поставки Windows). Откуда я взял {5EEC90AB-C022-44B2-A5DD-FD716A222A15}? Отладчик VS показал при просмотре уже упоминавшейся переменной _Microsoft_CRTProvider.
Запускаем hello.exe, видим классическое приветствие. Сбрасываем логи в файл,
logman stop test_crt_telemetry

и смотрим, что туда записалось:
tracerpt -summary summary.txt -o dumpfile.xml C:\temp\test_telemetry_000001.etl

<Events>
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
	<System>
		<Provider Name="Microsoft.CRTProvider" Guid="{5eec90ab-c022-44b2-a5dd-fd716a222a15}" />
		<EventID>17</EventID>
		<Version>0</Version>
		<Level>5</Level>
		<Task>0</Task>
		<Opcode>0</Opcode>
		<Keywords>0x200000000000</Keywords>
		<TimeCreated SystemTime="2016-04-11T00:57:29.437589800Z" />
		<Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
		<Execution ProcessID="7656" ThreadID="5796" ProcessorID="0" KernelTime="0" UserTime="0" />
		<Channel />
		<Computer />
	</System>
	<EventData>
		<Data Name="&quot;Main Invoked.&quot;">Main Invoked.</Data>
		<Data Name="FileName">C:\temp\hello.exe</Data>
	</EventData>
	<RenderingInfo Culture="ru-RU">
		<Task>InvokeMainViaCRT</Task>
	</RenderingInfo>
</Event>
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
	<System>
		<Provider Name="Microsoft.CRTProvider" Guid="{5eec90ab-c022-44b2-a5dd-fd716a222a15}" />
		<EventID>77</EventID>
		<Version>0</Version>
		<Level>5</Level>
		<Task>0</Task>
		<Opcode>0</Opcode>
		<Keywords>0x200000000000</Keywords>
		<TimeCreated SystemTime="2016-04-11T00:57:29.437734300Z" />
		<Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
		<Execution ProcessID="7656" ThreadID="5796" ProcessorID="0" KernelTime="0" UserTime="0" />
		<Channel />
		<Computer />
	</System>
	<EventData>
		<Data Name="&quot;Main Returned.&quot;">Main Returned.</Data>
		<Data Name="FileName">C:\temp\hello.exe</Data>
	</EventData>
	<RenderingInfo Culture="ru-RU">
		<Task>ExitMainViaCRT</Task>
	</RenderingInfo>
</Event>

Да, логи есть. Данных, впрочем, не особенно много: помимо собственно сообщения о вызове/возврате main() и стандартных заголовков ETW, пишется только имя exe-шника.

Кстати, а если оставить запись логов включённой и поработать? Можно поймать, например,

	<EventData>
		<Data Name="&quot;Main Invoked.&quot;">Main Invoked.</Data>
		<Data Name="FileName">C:\Program Files\Python 3.5\python35.dll</Data>
	</EventData>
	<EventData>
		<Data Name="&quot;Main Invoked.&quot;">Main Invoked.</Data>
		<Data Name="FileName">C:\Program Files\Python 3.5\python.exe</Data>
	</EventData>
	<EventData>
		<Data Name="&quot;Main Returned.&quot;">Main Returned.</Data>
		<Data Name="FileName">C:\Program Files\Python 3.5\python.exe</Data>
	</EventData>
	<EventData>
		<Data Name="&quot;Main Returned.&quot;">Main Returned.</Data>
		<Data Name="FileName">C:\Program Files\Python 3.5\python35.dll</Data>
	</EventData>

Python идёт в ногу с прогрессом!Пардон, Python 3 идёт в ногу с прогрессом!

Don't panic


Что мы имеем в итоге?
  • В любом бинарнике, скомпилированном VS2015 из программы на C или C++, есть код, который может писать логи. (зануда-mode: если не предпринимать специальных усилий по отключению стандартной библиотеки. Впрочем, если на Си ещё можно писать без неё, то на C++ — только до первого исключения)
  • Логи куцые, там нет ничего особенно интересного, что система и без того бы не знала. Можно различить случаи "main() штатно вернула управление" и «кто-то вызвал exit или abort», но это скорее интересно разработчику для отладки. Параноики могут расслабиться.
  • Но сам прецедент интересный.
  • По умолчанию логи никуда не пишутся. Их нужно включать специально. Однако, команда включения может вообще ничего не знать ни о программе, ни о предметной области (ни logman, ни tracerpt не в курсе о конкретном Microsoft.CRTProvider — вся структура логов выше пишется вместе с логами).
  • Проверить, включены ли логи, можно следующим кодом:
    #include <Windows.h>
    #include <evntprov.h>
    
    static void NTAPI EnableCallback(LPCGUID, ULONG isEnabled, UCHAR, ULONGLONG, ULONGLONG, PEVENT_FILTER_DESCRIPTOR, PVOID context)
    {
    	*(bool*)context = (bool)isEnabled;
    }
    
    typedef ULONG (WINAPI *EventSetInformation_t)(REGHANDLE, EVENT_INFO_CLASS, PVOID, ULONG);
    #pragma pack(push, 1)
    static struct {
    	unsigned short TotalSize;
    	char ProviderName[22];
    	unsigned short Chunk1Size;
    	unsigned char Chunk1Type;
    	GUID GroupGuid;
    } _Microsoft_CRTProvider_traits = {
    	0x2B,
    	"Microsoft.CRTProvider",
    	0x13,
    	1,
    	{ 0x4F50731A, 0x89CF, 0x4782, 0xB3, 0xE0, 0xDC, 0xE8, 0xC9, 0x04, 0x76, 0xBA },
    };
    static_assert(sizeof(_Microsoft_CRTProvider_traits) == 0x2B, "invalid size");
    #pragma pack(pop)
    
    int main()
    {
    	static const GUID providerId = { 0x5eec90ab, 0xc022, 0x44b2, 0xa5, 0xdd, 0xfd, 0x71, 0x6a, 0x22, 0x2a, 0x15 };
    	REGHANDLE hProvider;
    	bool enabled = false;
    	ULONG status = EventRegister(&providerId, &EnableCallback, &enabled, &hProvider);
    	if (status == ERROR_SUCCESS) {
    		EventSetInformation_t EventSetInformation = (EventSetInformation_t)GetProcAddress(GetModuleHandleA("advapi32.dll"), "EventSetInformation");
    		if (EventSetInformation)
    			EventSetInformation(hProvider, EventProviderSetTraits, &_Microsoft_CRTProvider_traits, sizeof(_Microsoft_CRTProvider_traits));
    		EventUnregister(hProvider);
    	}
    	printf("Microsoft.CRTProvider logging is %s\n", enabled ? "on" : "off");
    	return 0;
    }
    (под XP работать не будет в силу отсутствия необходимых API. Впрочем, по ровно той же причине логгинг под XP всегда отключён. exe-шник для ленивых: yadi.sk/d/pvQkFUqKqwJSV)
  • Такие логи логичнее всего было бы использовать как вспомогательное средство отладки. Но сам по себе запуск под отладчиком не включает логи. Конечно, не исключено, что какой-нибудь флажок в настройках включает функциональность, которой нужны логи… или логи нужны для какой-нибудь хитрой отладочной утилиты… но тогда непонятно, почему код остаётся при компиляции с релизной библиотекой.


  • UPD от 12:00 13.04.2016: обновил код детекта наличия активного потребителя логов, теперь он совсем точно соответствует происходящему внутри __vcrt_initialize_telemetry_provider.

Комментарии (18)


  1. bougakov
    12.04.2016 21:52
    +12

    Тэги к посту — прекрасны.


    1. VioletGiraffe
      13.04.2016 14:10
      +2

      «Именем админа» тоже понравилось, запомню :)


  1. kloppspb
    12.04.2016 22:29
    -17

    Глубокое IMHO: MS ни к C, ни к C++ давно никакого отношения не имеют, и в этом контексте рассматривать VS смысла нет.

    А что там в отдельно взятом компиляторе происходит до вызова main() и после — вопрос совсем другой. Приличные компиляторы обычно предоставляют информацию по RTL, вплоть до исходников.


    1. tangro
      13.04.2016 11:09
      +9

      MS ни к C, ни к C++ давно никакого отношения не имеют

      Ну да, всего лишь Герб Саттер (разработчик компилятора С++ в Microsoft) является президентом комитета по стандартизации С++, а сам компилятор от Microsoft — в тройке лучших в мире. А так да, не имеют.


  1. orcy
    13.04.2016 00:08
    +4

    Как-то обидно сейчас стало. Разве можно здесь зонды устанавливать, Microsoft?

    Возможно назвали бы они это не телеметрией, было бы не так неприятно, но все равно непонятно зачем так утяжелять рантайм.


    1. khdavid
      13.04.2016 11:27
      +2

      Ну логи по дефолту не пишутся, поэтому рантайм не утяжеляется.


      1. Jesus05
        13.04.2016 11:38

        Т.е. по вашему если в моей программе где-то без моего ведома дергаются WinApi функции это ее _совершенно_ не утяжеляет?


      1. grechnik
        13.04.2016 11:40
        -1

        Как минимум это занимает ощутимое место в exe-шнике.


        1. isotoxin
          13.04.2016 17:23
          +1

          По правде, много места оно не занимает. Я всегда линкую рантайм статически (не люблю лишние зависимости), но после перехода на VS2015 с VS2013 обнаружил, что почти все, что я собираю, стало чуточку меньше в размерах. Т.е. лишний код телеметрии не превышает выгоды от улучшенного оптимизатора новой студии.
          Но, соглашусь, сам факт наличия бесполезного кода вносит в мою тонкую душевную организацию немного хаоса.
          Для статически линкуемого рантайма способ отключения этой гадости я предложил в комменте ниже.


      1. orcy
        13.04.2016 12:12
        -1

        Все же утяжеляется, раз есть код который пишет логи когда они включены. Другой момент который меня беспокоит — когда мы линкуем райнтайм динамически, так на этапе разработки мы не можем знать как поведет себя логирование и телеметрия, Microsoft может обновить рантайм в апдейте Windows 10 и ваше приложение уже после выпуска будет отправлять в MS данные по полной.

        Еще один момент смущает, что Microsoft не включили исходники telemetry.cpp в поставку исходников RTL, значит есть что скрывать :-)


        1. grechnik
          13.04.2016 12:52

          Даже если мы линкуем рантайм статически, мы не можем знать, как поведёт себя логирование и телеметрия.
          hello.exe из статьи — вполне готовый бинарник, на его месте может быть любая собранная программа. А logman/tracerpt могут быть запущены совершенно независимо от него и от ведома разработчика hello.exe. В том числе апдейтом Windows. В том числе не трогающем vcruntime140.dll или как она там называется.


  1. sanja1989
    13.04.2016 11:33

    В Visual Studio 2013 такого не нашёл… но на работе не последнее обновление. А отключить телеметрию в исходниках пробовал кто-то?


    1. grechnik
      13.04.2016 11:36

      Да, это появилось только в VS 2015.


  1. McAaron
    13.04.2016 13:15
    -4

    Прологи и эпилоги для процессов, которые Вы внезапно обнаружили, существуют со времен первых мультизадачных ОС. Обычно о том, для чего это нужно, студенты соответсвующих специальностей изучают в курсе осперационных систем и системного программирования. Если посещать лекции по теории этих самых ОС, вопросов такого рода не возникнет. Дело в том, чтобы понять, что там и для чего, нужно изучить код планировщика. Без этого обсуждать crt никакого смысла не имеет. Всю эту «телеметрию» планировщик использует, чтобы принимать решения сугубо по Вашей программе, поэтому нет никакого смысла ее держать в ядре — достаточно юзерспейса.

    Относительно MSVC — при разработке на C/C++ для виндовсов это наихудший вариант выбора. Стандарты поддерживаются слабо, куча расширений, ухудшающих переносимость, очень неудобная IDE, скрывающая детали процесса компиляции и сборки, куча особенностей, потакающих программистам в их желаниях не комментировать изменения, плохая поддержка юникода, несогласованность в локалях даже в пределах этой самой MSVC.
    При этом в мире виндовсов есть отличные компиляторы, системы сборки проектов и редакторы исходных кодов, обладающие функциональностью, превышающей дешевое IDE MSVC кратно. Предоставляя крайне низкий уровень вхождения, свойственный основной массе школоты, MSVC выполняет главную роль в процессе огораживания и сегрегации программистов на индусов и гуру.


    1. grechnik
      13.04.2016 14:17
      +1

      Извините, ЧТО?
      Я бы предположил, что вы спутали код загрузчика приложений (ntdll.dll/ld-linux.so) и код рантайма конкретной среды программирования, но код загрузчика приложений тоже не имеет никакого отношения к планировщику.
      И не соблаговолит ли прилежный слушатель курса операционных систем и системного программирования просветить невежественную шпану типа меня, каким образом прослушивание такого курса избавляет от вопроса «что делает вызов __telemetry_main_invoke_trigger() непосредственно перед вызовом main()»?


    1. elmm
      14.04.2016 16:23

      Такое ощущение, что коммент занесло машиной времени, где-то на 10-15 лет в перёд, от момента написания.


  1. grechnik
    13.04.2016 14:07

    Ха. На Windows 10 без отключения телеметрии обновлённая версия детектора показывает, что система таки ведёт все логи. Только не уточняет, куда.


  1. isotoxin
    13.04.2016 15:59
    +4

    Спасибо. Добавил в свой проект:

    // disable VS2015 telemetry
    extern "C"
    {
        void _cdecl __vcrt_initialize_telemetry_provider() {}
        void _cdecl __telemetry_main_invoke_trigger() {}
        void _cdecl __telemetry_main_return_trigger() {}
        void _cdecl __vcrt_uninitialize_telemetry_provider() {}
    };