Thursday, August 28, 2008

OutOfMemoryException и как его побороть

Думаю, многие разработчики в своей практике сталкивались с такой неприятной исключительной ситуацией, как OutOfMemoryException. Чем она неприятна? Тем, что она свидетельствует об одной из двух вещей: либо ваше приложение скушало всю доступную память и сделало это ожидаемо, потому что вы его так запрограммировали, либо оно сделало это вследствие утечки памяти (memory leak). И первый, и второй случай чреваты серьезными проблемами. В первом случае нам нужно рефакторить код и, возможно, даже архитектуру с целью избежания этой ситуации в дальнейшем, и не факт, что при этом не придется придумывать какие-нибудь обходные методы. Во втором случае мы сталкиваемся с тем, что мы, скорее всего, понятия не имеем, где происходит утечка и как с этим бороться, то есть у нас налицо предстоящий достаточно сложный дебаг. И самое неприятное во всей этой ситуации то, что мы не знаем, с каким же все-таки вариантом мы имеет дело. А если не знаем, значит, самое время взять скальпель стетоскоп и прослушать пациента.

Для начала нужно разобраться с тем, как приложения (в нашем случае, веб-приложения) работают с памятью в Windows. Я думаю, многие замечали, что очень часто проблемы с OutOfMemoryException начинаются еще когда приложение только-только вышло за рубеж 1 Гб. Но ведь мы работаем в 32-битной системе, значит приложение может адресовать до 4 Гб памяти, не так ли? Не совсем. Дело в том, что из этих 4 Гб половину забирает себе Windows, а остальное делится между исполняющей средой .NET Framework и нашим приложением. Вот и получается, что памяти у нашего приложения не так уж и много. Заинтересовавшихся отсылаю за деталями к хорошей статье некоего Jesper’а, отличной ресторанной аналогии Tess и статье Johan Straarup.

Итак, попробуем разобраться, что же происходит внутри нашего приложения

Первый шаг очень простой: необходимо собрать как можно больше информации. Для начала общаемся с QA, которые нашли баг и пытаемся выяснить условия, при которых воспроизводится баг. OutOfMemoryException – исключение подлое, в большинстве случаев оно не воспроизводится в лоб, а просто вылетает в какой-то момент жизни приложения, когда память переполнится. Полученная информация нам поможет и для воспроизведения бага, и для собственного понимания того, что творится внутри процесса. В частности, у нас вот проблема в основном проявлялась при большом количестве пользователей, что неудивительно, так как сессии довольно большие, но все равно странно, так как непонятно, чем же занимается в таком случае сборщик мусора? Ну, о причинах этого потом – в примере.

Используем встроенные средства мониторинга ОС

На втором шаге мы пробуем минимальными усилиями разобраться с тем, что у нас происходит с памятью в процессе и сколько памяти у нас выделяется под сессию. Сделать это очень просто при помощи стандартных счетчиков производительности (performance counters) Windows. Нам пригодятся следующие как минимум счетчики, но вы можете воспользоваться и расширенным списком (помните, что включать их нужно для вашего процесса aspnet_wp/w3wp):

.NET CLR Memory/# Bytes in all heaps .NET CLR Memory/# Total committed Bytes .NET CLR Memory/# Total reserved Bytes .NET CLR Memory/Gen 0 heap size .NET CLR Memory/Gen 1 heap size .NET CLR Memory/Gen 2 heap size .NET CLR Memory/Large Object Heap Size

Выглядеть это будет примерно так:

Собственно, здесь мы хотим посмотреть размеры куч всех трех поколений и LOH, а также общую занятую память и committed/reserved bytes. Reserved bytes показывает, сколько наше приложение зарезервировало себе памяти, committed – сколько оно реально из этого количества уже использует. Отличное описание этих и других полезных счетчиков и их назначение можно найти здесь. Итак, запускаем счетчики и Windows Task Manager (с ним будем отслеживать Mem usage и VM usage для процесса aspnet_wp/w3wp), заполняем себе табличку в Excel – и поехали.

Примечание:

Настоятельно рекомендую перед работой с Task Manager прочитать пост Tess. В частности, там можно прочитать вот такую интересную вещь:

"If you want to see this in action, you can create a winforms application and allocate a bunch of objects and see the working set go up, and then if you minimize the app, the working set drops. This doesn't by any means mean that you have just released all this memory. It just means that you are looking at a counter that is totally irrelevant for determining how much stuff you store in memory :) Yet... this is the counter that people most often look at to determine memory usage...

I know that by now you are probably thinking "yeah right", you haven't even heard of this counter before, why would I say that this is the counter most people look at??? The answer is, because most people use task manager to look at memory usage of a process, and specifically look at the Memory Usage column. Surprise surprise:) what this actually shows you is the working set of the process...

If you want to see private bytes which is a far more interesting counter, you should look at the column in task manager that is labeled Virtual Memory Size (yeah, that's really intuitive:)), or better yet, look in performance monitor at process\private bytes and process\virtual bytes, there is no reason not to if your intent is to investigate high memory usage or a memory leak. "

Так что будьте осторожны ;)

Логинимся в приложение одним пользователем, делаем замеры, логинимся следующим, делаем замеры. По пути можно попробовать просмотреть разную функциональность системы, чтобы увидеть, где именно мы получаем большое увеличение памяти. По размерам куч видим, как постепенно увеличивается количество памяти, и что у нас чистится GC, а что – нет. По Mem usage и VM usage определяем общее количество используемой памяти и пытаемся путем несложных арифметических операций определить, сколько же все-таки у нас занимает один пользователь в сессии. В нашем случае уже на 10 пользователях приходит понимание, что общее количество памяти растет непомерно и освобождаться почему-то не хочет. Ну, это логично – созданные сессии еще активны и сборщик мусора их собрать не может. Ставим опыт: отпускаем приложение на уровне 700 Мб и уходим на полчаса пить чай. Через полчаса заходим на сайт новым пользователем и делаем очередной замер. Нет, почти ничего не изменилось, используемая память продолжает увеличиваться, хотя должна была существенно уменьшится. Размер одной сессии в среднем – 30-40 Мб, что слишком много. Итак, либо у нас по какой-то причине не очищаются сессии, либо утечка памяти в другом месте. Информации по-прежнему мало. Пора браться за более серьезные инструменты анализа.

Знакомимся с тяжелой артиллерией

В роли тяжелой артиллерии может выступать практически любой performance tool, который умеет нормально мониторить память. Тулов много, но толковую информацию предоставляют единицы. Лично я все не смотрел, но вот мой любимый dotTrace, который не раз помогал мне находить performance-проблемы в коде, здесь полностью облажался. Ничего толкового из него я добиться не смог, может, просто руки кривые :) Поэтому, если у вас нет особых вариантов, то советую сразу же взяться за WinDbg. WinDbg – это универсальный дебаггер, которая позволяет отлаживать любые win-приложения. А самое классное в нем то, что он позволяет не только подключаться к приложению и отлаживать в онлайн-режиме, но умеет еще и анализировать т.н. user dump’ы, то есть снимки внутреннего состояния приложения. Сделать эти снимки можно при помощи тулы User Mode Process Dumper, а WinDbg можно найти в пакете Debugging Tools for Windows. Итак, выполним подготовительные действия по шагам:

1) Устанавливаем оба пакета: Dumper на сервер приложения, Tools на девелоперскую.
2) Загружаем наше приложение так, чтобы оно начало валяться и дрыгать ногами. Необязательно добиваться OutOfMemoryException, можно просто подождать, пока приложение скушает около гигабайта памяти.
3) Делаем дамп памяти, запустив userdump.exe из соответствующего каталога как минимум с одним параметром – идентификатором процесса ASP.NET. Узнать pid можно несколькими способами, самый простой – через колонку PID в Task Manager. Строка запуска будет выглядеть где-то так:
userdump.exe 1234
где 1234 – идентификатор процесса.
Также можно дополнительно указать, куда складывать dump-файл. Если вы не укажете куда, не забудьте глянуть, что по этому поводу вам напишет userdump. Дамп занимает около минуты, в зависимости от размера процесса.
4) Открываем WinDbg и через File -> Open Crash Dump загружаем дамп в приложение

После всех указанных действий вы увидите картинку наподобие следующей:

Анализируем дамп процесса

Первым делом нам необходимо подключить к WinDbg библиотеку команд для отлаживания .NET-приложений. Называется эта библиотека sos.dll и для .NET 2.0 она входит в поставку фреймворка, поэтому лежит обычно по следующему пути:

C:\<windows_home>\Microsoft.NET\Framework\v2.0.50727\sos.dll.

Для .NET 1.1 библиотеку можно найти по немного другому адресу:

%DEBUGGING_TOOLS_HOME%\clr10

Теперь подключаем sos.dll к WinDbg при помощи команды:

.load C:\<windows_home>\Microsoft.NET\ Framework\v2.0.50727\sos.dll

Теперь наш дебаггер пополнился кучей дополнительных команд. Чтобы посмотреть их все, наберите в консоли команду "!help". Вот список команд версии sos.dll для .NET 2.0:

Как видите, команд здесь довольно много. Я не буду останавливаться на всех них. Подробное описание процесса инсталляции и команд можно найти в секции Debugging School блога Johan Straarup:

Инсталляция: How to install Windbg and get your first memory dump
Список комманд: Getting started with windbg - part I, Getting started with windbg - part II, Using WinDbg - Advanced commands
Решение различных проблем: Using WinDbg - Hunting Exceptions, Walkthrough - Troubleshooting a native memory leak

Теперь, когда мы знаем минимально необходимый набор команд, я покажу приблизительный алгоритм поиска источника проблемы.

Начнем мы с анализа памяти. Проверим, что у нас вообще творится в куче:

0:000> !eeheap -gc
Number of GC Heaps: 8
------------------------------
Heap 0 (000dacf8)
generation 0 starts at 0x33187580
generation 1 starts at 0x33180038
generation 2 starts at 0x02960038
ephemeral segment allocation context: none
segment begin allocated size
1b63e3f0 6c10260c 6c105d38 0x0000372c(14124)
1b5fd5b0 7b463c40 7b47a744 0x00016b04(92932)
1b5ce420 6c267294 6c26d410 0x0000617c(24956)
000eb0d8 7a733370 7a754b98 0x00021828(137256)
000e8750 790d8620 790f7d8c 0x0001f76c(128876)
02960000 02960038 048419dc 0x01ee19a4(32381348)
33180000 33180038 332cb58c 0x0014b554(1357140)
Large object heap starts at 0x12960038
segment begin allocated size
12960000 12960038 1394a698 0x00fea660(16688736)
29fa0000 29fa0038 2a82b8c0 0x0088b888(8960136)
Heap Size 0x3904120(59785504)
------------------------------
Heap 1 (000dbcd0)

...
Heap Size 0x4195f68(68771688)
------------------------------
Heap 2 (000dd1e8)

...
Heap Size 0x3d09fb4(64004020)
------------------------------
Heap 3 (000de6d0)

...
Heap Size 0x38a3fbc(59391932)
------------------------------
Heap 4 (000dfdf0)

...
Heap Size 0x390c360(59818848)
------------------------------
Heap 5 (000e10f0)

...
Heap Size 0x36b2fc8(57356232)
------------------------------
Heap 6 (000e2600)

...
Heap Size 0x3f69ef8(66494200)
------------------------------
Heap 7 (000e3b10)

...
Heap Size 0x39411f0(60035568)
------------------------------

GC Heap Size 0x1d8b2408(495657992)

Я сознательно опустил некоторые не очень важные подробности. Главное, что мы отсюда видим – что у нас 8 куч (по количеству ядер, виртуальных, и не только) и общий размер этих куч составляет около полугигабайта, что есть немало. Значит, кто-то там живет. Теперь выведем статистику по хранящимся в куче объектам:

0:000> !dumpheap -stat
------------------------------
Heap 0
total 359790 objects
------------------------------
Heap 1
total 325369 objects
------------------------------
Heap 2
total 384784 objects
------------------------------
Heap 3
total 424903 objects
------------------------------
Heap 4
total 379269 objects

------------------------------
Heap 5
total 346442 objects
------------------------------
Heap 6
total 410719 objects
------------------------------
Heap 7
total 367846 objects
------------------------------
total 2999122 objects
Statistics:
MT Count TotalSize Class Name
7ae7ab58 1 12 System.Drawing.ColorConverter
7a776af8 1 12 System.Diagnostics.CorrelationManager
7a75b4dc 1 12 System.CodeDom.Compiler.CodeDomConfigurationHandler
7a75b1ac 1 12 System.Net.DefaultCertPolicy
7a75a2e4 1 12 System.ComponentModel.TimeSpanConverter
7a759dc4 1 12 System.ComponentModel.SingleConverter
7a759c2c 1 12 System.ComponentModel.Int32Converter
7a759b5c 1 12 System.ComponentModel.StringConverter

7a759a70 1 12 System.ComponentModel.DoubleConverter
7a759824 1 12 System.ComponentModel.BooleanConverter
...
6639d878 1 12 System.Web.Caching.Cache
...
663b0cdc 6 288 System.Web.SessionState.InProcSessionState
...
6641194c 39326 629216 System.Web.UI.StateBag
1f49c0c4 11174 670440 System.Data.Objects.DataClasses.EntityReference`1[[Custom.Domain.Model.Identity, CUSTOM.Domain]]
79104368 29236 701664 System.Collections.ArrayList
1f4e6b2c 6899 814452 System.Collections.Generic.Dictionary`2+Entry[[System.String, mscorlib],[System.Data.Mapping.ObjectMemberMapping, System.Data.Entity]][]
7a7580d0 42592 851840 System.Collections.Specialized.HybridDictionary
79109778 16469 922264 System.Reflection.RuntimeMethodInfo
7a75820c 33900 949200 System.Collections.Specialized.ListDictionary
1f47b648 24872 994880 System.Collections.Generic.HashSet`1[[System.Data.Mapping.ViewGeneration.Structures.CellConstant, System.Data.Entity]]
1ed28b24 26572 1169168 Custom.Domain.Model.ModelChangeNotification
663c1de8 76432 1222912 System.Web.UI.StateItem
1f47d600 24872 1273584 System.Collections.Generic.HashSet`1+Slot[[System.Data.Mapping.ViewGeneration.Structures.CellConstant, System.Data.Entity]][]
7912d9bc 6241 1379616 System.Collections.Hashtable+bucket[]
1f670640 59056 1417344 System.Collections.Generic.List`1[[System.Data.Objects.DataClasses.RelatedEnd, System.Data.Entity]]
7a7582d8 75305 1506100 System.Collections.Specialized.ListDictionary+DictionaryNode
1fb88ec4 27196 1631760 System.Data.Objects.DataClasses.EntityReference`1[[Custom.Domain.Model.ChangeSet, CUSTOM.Domain]]
79102290 141087 1693044 System.Int32
1f67044c 60893 1705004 System.Data.Objects.DataClasses.RelationshipManager
1f671b90 69 1826948 System.Collections.Generic.Dictionary`2+Entry[[System.Data.EntityKey, System.Data.Entity],[System.Data.Objects.ObjectStateEntry, System.Data.Entity]][]
1f6720fc 116747 2334940 System.Data.Objects.RelationshipWrapper
1f497584 49230 2953800 System.Data.Objects.DataClasses.EntityReference`1[[Custom.Domain.Model.User, CUSTOM.Domain]]
7912dae8 3769 3262224 System.Byte[]
1f670984 66309 3448068 System.Data.Objects.EntityEntry
1f672fec 64 3699100 System.Collections.Generic.Dictionary`2+Entry[[System.Data.Objects.RelationshipWrapper, System.Data.Entity],[System.Data.Objects.ObjectStateEntry, System.Data.Entity]][]
1f6743a4 164482 3947568 System.Data.Objects.DataClasses.RelationshipNavigation
1f65151c 118239 4729560 System.Data.EntityKey
1f67223c 116740 6070480 System.Data.Objects.RelationshipEntry
7912d7c0 55276 6703116 System.Int32[]
7912d8f8 224375 12356408 System.Object[]

000d9080 1518 31164860Free
790fd8c4 318231 362482876 System.String

Здесь мы тоже видим довольно много интересного. Во-первых, для будущих тестов нам нужны MT (что-то типа идентификатора типа объекта) объектов System.Web.Caching.Cache и System.Web.SessionState.InProcSessionState, которые соответствуют глобальному кешу приложения и его сессиям, которые наравне с другими объектами кеша хранятся в нем. Еще мы видим, что у нас очень много объектов хранится в массивах строк, но толку нам пока от этого немного. Вот если бы там были какие-то более специфические объекты, например, DataTable, мы могли бы туда сходить и посмотреть более серьезно. А так глянем сначала, сколько у нас занимается кеш в целом и сессии в частности. Для этого сначала нужно найти адреса этих объектов:

0:000> !dumpheap -mt 6639d878
------------------------------
Heap 0
Address MT Size
total 0 objects
------------------------------
Heap 1
Address MT Size
total 0 objects
------------------------------
Heap 2
Address MT Size
total 0 objects
------------------------------
Heap 3
Address MT Size
total 0 objects
------------------------------
Heap 4
Address MT Size
total 0 objects

------------------------------
Heap 5
Address MT Size
total 0 objects
------------------------------
Heap 6
Address MT Size

0e961294 6639d878 12
total 1 objects
------------------------------
Heap 7
Address MT Size
total 0 objects
------------------------------
total 1 objects
Statistics:
MT Count TotalSize Class Name
6639d878 1 12 System.Web.Caching.Cache
Total 1 objects
0:000> !objsize 0e961294
sizeof(0e961294) = 336106272( 0x14089320) bytes (System.Web.Caching.Cache)
0:000> !dumpheap -mt 663b0cdc
------------------------------
Heap 0
Address MT Size

0355a598 663b0cdc 48
03969aa0 663b0cdc 48
039711e4 663b0cdc 48
total 3 objects
------------------------------
Heap 1
Address MT Size
total 0 objects
------------------------------
Heap 2
Address MT Size

07f62150 663b0cdc 48
total 1 objects
------------------------------
Heap 3
Address MT Size

08f53ec8 663b0cdc 48
total 1 objects
------------------------------
Heap 4
Address MT Size
total 0 objects
------------------------------
Heap 5
Address MT Size
total 0 objects
------------------------------
Heap 6
Address MT Size
total 0 objects
------------------------------
Heap 7
Address MT Size

10d01948 663b0cdc 48
total 1 objects
------------------------------
total 6 objects
Statistics:
MT Count TotalSize Class Name
663b0cdc 6 288 System.Web.SessionState.InProcSessionState
Total 6 objects

Итак, кеш весит 336 Мб, а сессий у нас 6 штук. Берем первую попавшуюся и смотрим ее размер:

0:000> !objsize 0355a598
sizeof(0355a598) = 335808888( 0x14040978) bytes (System.Web.SessionState.InProcSessionState)

Смотрим следующую – размер тот же, причем до байта. Еще одну – аналогично. Явно что-то не так в датском королевстве. Суммарный размер 6 сессий будет явно превышать размер объекта кеша, чего не может быть в принципе, так как объект Cache содержит в себе сессии. Однако, здесь есть особенность, которая может объяснить эту нестыковку – дело в том, что sos при подсчете размера объекта включает в него и размер всех объектов, на которые данный объект ссылается. Значит, у нас где-то сессии друг на друга ссылаются. Вот только где и как? Кроме того, мы можем сделать еще один важный вывод: чистая информация, которую мы вносили в кеш руками, занимает очень мало памяти, что очень хорошо. Если бы разница была больше, то нужно было бы идти анализировать еще и закешированные данные.

Посмотрим, что у нас хранится в сессии:

0:000> !do 10d01948
Name: System.Web.SessionState.InProcSessionState
MethodTable: 663b0cdc
EEClass: 663b0c6c
Size: 48(0x30) bytes
(C:\WINDOWS\assembly\GAC_32\System.Web\2.0.0.0__b03f5f7f11d50a3a\System.Web.dll)
Fields:
MT Field Offset Type VT Attr Value Name

663ea4e4 4001edc 4 ...ateItemCollection 0 instance 0704f73c _sessionItems
663a9944 4001edd 8 ...ObjectsCollection0 instance 00000000 _staticObjects
79102290 4001ede c System.Int32 1 instance 25 _timeout
7910be50 4001edf 18 System.Boolean 1 instance 0 _locked
7910c878 4001ee0 1c System.DateTime 1 instance 10d01964 _utcLockDate
79102290 4001ee1 10 System.Int32 1 instance 36 _lockCookie
663a7220 4001ee2 24 ...ReadWriteSpinLock 1 instance 10d0196c _spinLock
79102290 4001ee3 14 System.Int32 1 instance 0 _flags
0:000> !do 0704f73c
Name: System.Web.SessionState.SessionStateItemCollection
MethodTable: 664107dc
EEClass: 66410764
Size: 60(0x3c) bytes
(C:\WINDOWS\assembly\GAC_32\System.Web\2.0.0.0__b03f5f7f11d50a3a\System.Web.dll)
Fields:
MT Field Offset Type VT Attr Value Name
7910be50 4001172 24 System.Boolean 1 instance 0 _readOnly

79104368 4001173 4 ...ections.ArrayList 0 instance 0704f784 _entriesArray
79116ef8 4001174 8 ...IEqualityComparer0 instance 02961a28 _keyComparer
79101fe4 4001175 c ...ections.Hashtable 0 instance 0704f79c _entriesTable
7a75a878 4001176 10 ...e+NameObjectEntry 0 instance 00000000 _nullKeyEntry
7a772bc4 4001177 14 ...se+KeysCollection 0 instance 00000000 _keys
79111df0 4001178 18 ...SerializationInfo 0 instance 00000000 _serializationInfo
79102290 4001179 20 System.Int32 1 instance 6 _version
790fd0f0 400117a 1c System.Object 0 instance 00000000 _syncRoot
791168f8 400117b 538 ...em.StringComparer 0 shared static defaultComparer
>> Domain:Value 000c8390:NotInit ... <<
7910be50 4001f2b 25 System.Boolean 1 instance 1 _dirty
66421eb8 4001f2c 28 ...n+KeyedCollection 0 instance 00000000 _serializedItems
79101924 4001f2d 2c System.IO.Stream 0 instance 00000000 _stream
79102290 4001f2e 34 System.Int32 1 instance 0 _iLastOffset
790fd0f0 4001f2f 30 System.Object 0 instance 0704f778 _serializedItemsLock
79101fe4 4001f2a c5c ...ections.Hashtable 0 shared static s_immutableTypes
>> Domain:Value 000c8390:NotInit ..
. <<
0:000> !do 0704f784
Name: System.Collections.ArrayList
MethodTable: 79104368
EEClass: 791042bc
Size: 24(0x18) bytes
(C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
Fields:
MT Field Offset Type VT Attr Value Name

7912d8f8 40008ea 4 System.Object[] 0 instance 10d0189c _items
79102290 40008eb c System.Int32 1 instance 2 _size
79102290 40008ec 10 System.Int32 1 instance 2 _version
790fd0f0 40008ed 8 System.Object 0 instance 00000000 _syncRoot
7912d8f8 40008ee 1c0 System.Object[] 0shared static emptyArray
>> Domain:Value 000c8390:08961f48 ...<<
0:000> !da 10d0189c
Name: System.Object[]
MethodTable: 7912d8f8
EEClass: 7912de6c
Size: 32(0x20) bytes
Array: Rank 1, Number of elements 4, Type CLASS
Element Methodtable: 790fd0f0

[0] 10d0188c
[1] 034f5ccc
[2] null
[3] null
0:000> !do 10d0188c
Name: System.Collections.Specialized.NameObjectCollectionBase+NameObjectEntry
MethodTable: 7a75a878
EEClass: 7a7c51c4
Size: 16(0x10) bytes
(C:\WINDOWS\assembly\GAC_MSIL\System\2.0.0.0__b77a5c561934e089\System.dll)
Fields:
MT Field Offset Type VT Attr Value Name
790fd8c4 400117c 4 System.String 0 instance 0698fdd8 Key

790fd0f0 400117d 8 System.Object 0 instance 030cc5d8 Value
0:000> !do 030cc5d8
Name: Custom.Namespace.SomeClass

MethodTable: 1b109548
EEClass: 1d351918
Size: 116(0x74) bytes
(C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\Temporary ASP.NET Files\someApp-3.7.23.30\196191ae\903c3217\assembly\dl3\5f395f40\004dd5b1_3ffec801\Custom.UI.Web.DLL)

Fields:
MT Field Offset Type VT Attr Value Name

1b10e18c 400006e 4 ...del.DomainContext 0 instance 030cc6f0 model
1b10d484 400006f 8 ...OrganizationScope0 instance 0ec75578 scopeModel
1fe48b6c 4000070 c ...el.TotalViewModel 0 instance 00000000 totalViewModel
1b3dac14 4000071 10 ...odel.Organization 0 instance 08f552bc organizationModel
1fb80314 4000072 14 ...on.Model.Variable 0 instance 00000000 variableModel
1fbe7afc 4000073 18 ...Model.Requirement 0 instance 00000000 requirementModel
1b3dbcc4 4000074 1c ...n.Model.Objective 0 instance 00000000 objectiveModel
1fbe938c 4000075 20 ...uirementAttribute 0 instance 0f3843ac requirementAttributeModel
7910ff9c 4000076 24 System.Void 0 instance 00000000 requirementAttributeClassModel
1b3dba6c 4000077 28 ...ion.Model.Project 0 instance 00000000 projectModel
1b3db714 4000078 2c ...cation.Model.Task 0 instance 00000000 taskModel
7910ff9c 4000079 30 System.Void 0 instance 00000000 profileModel
1b3db48c 400007a 34 ...on.Model.Resource 0 instance 00000000 resourceModel
7910ff9c 400007b 38 System.Void 0 instance 00000000 commentModel
1ed25b14 400007c 3c ...on.Model.Identity 0 instance 00000000 identityModel
30f67d1c 400007d 40 ....Model.DataModule 0 instance 00000000 dataModuleModel
1ed25e14 400007e 44 ...cation.Model.User 0 instance 0ec74f7c userModel
1fb81614 400007f 48 ...cation.Model.Role 0 instance 0ec75068 roleModel
1fb8146c 4000080 4c ...Web.Model.CCFUser 0 instance 0ec74ffc currentUser
1b3db174 4000081 50 ...tion.Model.Folder 0 instance 0f36b6d4 folderModel
1fc814c4 4000082 54 ...on.Model.Document 0 instance 0d0d93cc documentModel
1b10ed0c 4000083 58 ...on.Model.Workflow 0 instance 030cc66c workflowModel
1fc83ebc 4000084 5c ...odel.Notification 0 instance 031958ec notificationModel
7910ff9c 4000085 60 System.Void 0 instance 00000000 reportModel
1b10f6fc 4000086 64 ...n.Model.ChangeSet 0 instance 050cc0a0 changeSetModel
7910ff9c 4000087 68 System.Void 0 instance 00000000 scheduledTasksManagerModel
1b3dc034 4000088 6c ...esWorkflowMonitor 0 instance 00000000 changesWorkflowMonitor
1fb8c638 4000089 34 ...hing.RequestCache 0 static 109e1158 requestCache
1fe44870 400008a 38 ....ApplicationCache 0 static 0aee10c4 applicationCache
1ed24714 400008b 3c ...g.StatisticsCache 0 static 0c9a4e7c statisticsCache

Как мы видим, в сессии хранится лишь некий экземпляр класса Custom.Namespace.SomeClass, который содержит перечисленный набор полей. В принципе, это известно давно тем, кто приложение программировал :) Колонка Value показывает значения ссылок, нолики, как несложно догадаться – это null. Теперь посмотрим размеры объекта model:

0:000> !objsize 030cc6f0
sizeof(030cc6f0) = 335808160( 0x140406a0) bytes (Custom.Namespace.SomeAnotherClass)
0:000> !do 030cc6f0
Name: Custom.Namespace.SomeAnotherClass
MethodTable: 1b10e18c
EEClass: 1d35c7d8
Size: 48(0x30) bytes
(C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\Temporary ASP.NET Files\someApp-3.7.23.30\196191ae\903c3217\assembly\dl3\0a41ba0b\0020a4b0_3ffec801\Custom.Application.DLL)
Fields:
MT Field Offset Type VT Attr Value Name

1dad2c38 4000119 4 ...Views.DomainLogic 0 instance 050cbf34 context
7910be50 400011a 28 System.Boolean 1 instance 0 isChanged
00000000 400011b 8 0 instance 030cc720 workflowModelChanges
00000000 400011c c 0 instance 030cc738 notificationsChanges
1fb804fc 400011d 10 ...olledBackDelegate 0 instance 0f3843e4 ContextRolledBack
1fb805ec 400011e 14 ...RefreshedDelegate 0 instance 0f384424 ContextRefreshed
1b10f4d4 400011f 18 ...extSavingDelegate 0 instance 050cc040 ContextSaving
1b10f8e4 4000120 1c ...textSavedDelegate 0 instance 0d0d9cbc ContextSaved
1fb806dc 4000121 20 ...aveFailedDelegate 0 instance 0f384464 ContextSaveFailed
1b10f5c4 4000122 24 ...CancelledDelegate 0 instance 050cc060 ContextSaveCancelled
7910be50 4000123 29 System.Boolean 1 instance 0k__BackingField
0:000> !objsize 050cbf34
sizeof(050cbf34) = 63643700 ( 0x3cb2034) bytes (Custom.Namespace.OneMoreAnotherClass)

Итак, главный объект SomeAnotherClass весит около 335 Мб, в то время как вложенный в него OneMoreAnotherClass – всего 63 Мб. Возможно, другие объекты содержат остальные данные? Проверяем – нет, не так. Хотя в нашем случае даже проверять не нужно было – мы и так знаем свой код :) Проверяем другие сессии аналогичным образом – там та же картина, что вполне ожидаемо. Итак, к чему мы пришли? Наш Custom.Namespace.SomeClass и вложенный в него Custom.Namespace.SomeAnotherClass содержится в каждой сессии, а то, что objsize показывает для него размер всех сессий, указывает, что на этом уровне у нас возможны проблемы.

А теперь посмотрим, кто на кого ссылается:

0:000> !gcroot 030cc6f0
Note: Roots found on stacks may be false positives. Run "!help gcroot" for more info.
Scan Thread 17 OSTHread c64
Scan Thread 27 OSTHread 1c24
Scan Thread 28 OSTHread 824
Scan Thread 29 OSTHread 1d68
Scan Thread 15 OSTHread 1ee4
Scan Thread 31 OSTHread ec4
Scan Thread 32 OSTHread 1ea4
Scan Thread 33 OSTHread 1e9c
Scan Thread 34 OSTHread 3ec
Scan Thread 35 OSTHread 1e10
Scan Thread 36 OSTHread 6ec
Scan Thread 37 OSTHread c90
Scan Thread 38 OSTHread b6c
ESP:1f17ecbc:Root:069b83b8(Microsoft.Practices.EnterpriseLibrary.Common.Configuration.Storage.ConfigurationChangeFileWatcher)->
069b8514(System.Threading.Thread)->
08963fe0(System.Runtime.Remoting.Contexts.Context)->
08963e40(System.AppDomain)->
0a935d24(System.ResolveEventHandler)->
0a0e9918(System.Object[])->
0e9a9c34(System.ResolveEventHandler)->
0e9a9250(System.Web.Compilation.BuildManager)->
0e9a9e38(System.Web.Compilation.MemoryBuildResultCache)->
0e96137c(System.Web.Caching.CacheMultiple)->
0e961394(System.Object[])->
0e9679dc(System.Web.Caching.CacheSingle)->
0e967aa0(System.Web.Caching.CacheExpires)->
0e967ac0(System.Object[])->
0e9685d4(System.Web.Caching.ExpiresBucket)->
118ede14(System.Web.Caching.ExpiresPage[])->
118ede98(System.Web.Caching.ExpiresEntry[])->
03971214(System.Web.Caching.CacheEntry)->
039711e4(System.Web.SessionState.InProcSessionState)->
0b5fa220(System.Web.SessionState.SessionStateItemCollection)->
0b5fa280(System.Collections.Hashtable)->
0b5fa2b8(System.Collections.Hashtable+bucket[])->
03971170(System.Collections.Specialized.NameObjectCollectionBase+NameObjectEntry)->
0d7b54d4(Custom.Namespace.SomeClass)->
0d7b5568(Custom.Application.Model.Workflow)->
0d7b55ac(Custom.Application.Model.Workflow+WorkflowRemindDelegate)->
0698fec8(Custom.ApproveActionWorkflow.WorkflowManager)->

11bdadd4(Custom.ApproveActionWorkflow.WorkflowManager+WorkflowNotificationsSentDelegate)->
03971088(System.Object[])->
050cc020(Custom.ApproveActionWorkflow.WorkflowManager+WorkflowNotificationsSentDelegate)->
030cc6f0(Custom.Namespace.SomeAnotherClass)
DOMAIN(001020B0):HANDLE(Strong):29310e0:Root:0e968b38(System.Threading._TimerCallback)->
0e968af0(System.Threading.TimerCallback)->
0e964010(System.Web.Caching.CacheExpires)->
0e964030(System.Object[])->
0e9646f8(System.Web.Caching.ExpiresBucket)->
0517489c(System.Web.Caching.ExpiresPage[])->
05174920(System.Web.Caching.ExpiresEntry[])->
10d01978(System.Web.Caching.CacheEntry)->
10d01948(System.Web.SessionState.InProcSessionState)->
0704f73c(System.Web.SessionState.SessionStateItemCollection)->
0704f79c(System.Collections.Hashtable)->
0704f7d4(System.Collections.Hashtable+bucket[])->
10d0188c(System.Collections.Specialized.NameObjectCollectionBase+NameObjectEntry)->
030cc5d8(Custom.Namespace.SomeClass)->

030cc6f0(Custom.Namespace.SomeAnotherClass)

А вот и корень зла. Если посмотреть этот trace, то можно увидеть, что поначалу у нас все замечательно, кеш, сессия, а потом начинаются странности. Откуда-то появляются ссылки через делегаты, а класс SomeAnotherClass вообще фигурирует дважды, причем по разным адресам. Однако подсказка тоже есть – Custom.ApproveActionWorkflow.WorkflowManager+WorkflowNotificationsSentDelegate. Немного подумав, вспоминаем, что у нас есть замечательный синглтон-класс WorkflowManager, который предназначен для взаимодействия между пользовательскими потоками и потоком WorkflowRuntime, и оповещает все сессии при помощи генерации события о том, что им пора бы обновить некоторые специфические данные из базы. И он, конечно же, подписывает все создаваемые сессии на свое событие. А потом держит эту ссылку бесконечно, таким образом не давая сборщику мусора собрать сессии. Ну все, разобрались. Теперь дело за малым: зарефакторить код, чтобы сессии сами опрашивали класс об изменениях и избавиться от OutOfMemoryException :) Дело сделано.

Выводы

Выводы из данной ситуации очень простые:

1) Делегаты, как оказывается – звери совсем не безобидные, за ними тоже нужен глаз да глаз
2) Старайтесь внимательно реализовывать межсессионное взаимодействие, чтобы не допускать не только ссылок на объекты, но и на функции
3) Не забывайте про особенности работы Task Manager и то, что он реально показывает. Не нужно на него сильно полагаться
4) Если же у вас все-таки вылетает OutOfMemoryException, не отчаивайтесь. Вооружайтесь дампом и WinDbg – и вперед. Люди и не такие баги отлаживают :)
5) WinDbg подойдет и для отладки других сложных ситуаций. Вот, например, рассказ Юры Скалецкого и некоего JKealey. Там есть что почитать.

Ну, и напоследок я настоятельно вам советую следующие статьи из блога Tess и Johan’а по поводу отладки утечек памяти:

Debugging Script: Dumping out ASP.NET Session Contents
ASP.NET Memory Leak Case Study: Sessions Sessions Sessions…
ASP.NET Memory - How much are you caching? + an example of .foreach
ASP.NET Case Study: Tracing your way to Out Of Memory Exceptions
Why adding more memory won't resolve OutOfMemoryExceptions
I am getting OutOfMemoryExceptions. How can I troubleshoot this?
Are you getting OutOfMemoryExceptions when uploading large files?

Да и вообще, эти блоге стоит добавить в ваш персональный RSS feeder. Можно вместе с блогом Марка Руссиновича (ага, это тот, который написал кучу полезных системных тулов, известных под названием Sysinternals). Пригодятся.

Успехов в отладке!

Tuesday, August 12, 2008

Entity Framework: Vote Of Confidence

Данный пост навеян долгожданным релизом EF и нашумевшим ADO .NET Entity Framework Vote of No Confidence. В целом, критика EF достаточно грамотная и заслуженная. Первую версию EF действительно не стоит считать волшебной палочкой, которая сможет мало того, что решить ваши проблемы, но еще и удовлетворить всех желающих цветом, формой и набором заклинаний. Однако, это достаточно полноценный и на удивление малобажный ORM (баги дизайнера в бета-версии, думаю, не в счет, они уже почти все пофикшены), который уже сейчас можно использовать. Если есть желание, конечно. А желание можно подкрепить вот этим ответом на Vote of No Confidence. Из своего полугодового опыта работы еще с бетой 3 могу лишь добавить, что я считаю реальной проблемой лишь 3 пункта: отсутствие lazy loading, Anemic Domain Model anti-pattern и действительно заколебавший designer-код в edmx-файле, который создает проблемы с мержем. Lazy loading мы пофиксили при помощи custom tool и CodeDOM (если интересны подробности, вам сюда, сюда или даже сюда), который встраивается в pipeline и генерирует нам cs-файл с сущностями, поддерживающими ленивый образ жизни. С Anemic Domain Model не все так просто и лично меня беспокоит проблема написания unit-тестов для сущностей EF. Впрочем, анализ этой проблемы мы пока оставим до лучших времен, а для большинства задач подойдут partial-классы или кодогенерация. Дизайнер в SP1 значительно улучшился, в нем пофиксили часть надоевших багов, но, насколько я знаю, секцию designer из edmx-файла пока не вынесли. Подождем.

Резюмируя, могу сказать, что в целом Entity Framework уже сейчас оправдывает ожидания и позволяет решать широкий спектр задач. Конечно, он не лишен недостатков, но меня радует тот факт, что MS начала прислушиваться к мнению community и сделала процесс дизайна следующей версии более открытым (добро пожаловать на блог EF Design), а не просто делает что-то за ширмой. Фактом является также и то, что EF будет развиваться, в отличие от того же Linq to SQL, который стоит использовать лишь для небольших приложений. Так что сейчас у нас уже есть реальная альтернатива стандартной модели работы с данными ADO.NET. В приложении критичен performance, вы разрабатываете социальную сеть или электронный магазин – вам лучше использовать старый дедовский способ, важна скорость и удобство разработки – берите ORM: NHibernate, Active Record, EF или что-то еще. Пишете небольшое приложение – к вашим услугам Linq to SQL или даже ActionPack. Кому интересно узнать про EF подетальнее, рекомендую подкасты с Julie Lerman (на .NET Rocks), Daniel Simmons (про релиз v1 и вообще на .NET Rocks) и Mike Pizzo (на Hanselminutes), а также блоги все той же Julie и Daniel.

Thursday, July 31, 2008

Хамар-Дабан, пик Черского

Меня всегда интересовало, что люди ищут в горах. Зачем эти альпинисты взбираются на высоченные горы против сильного ветра, тащат на себе тяжеленные рюкзаки, спят в холодных палатках? Неужели все это лишь ради того, чтобы забраться на гору и почувствовать себя хотя бы на минутку на вершине мира? Или все же ради чего-то другого? Мне кажется, сейчас я знаю ответ.

Хамар-Дабан – это горная цепь, протянувшаяся на 350 км от Улан-Удэ на востоке до юго-западной точки Байкала на западе. Высочайшая точка хребта – г. Хан-Ула (2371 м). На западе Хамар-Дабан граничит с Саянами, на севере огибает Байкал, на юге переходит границу с Монголией. С Хамар-Дабана в Байкал течет большое количество рек, здесь проходит много туристических маршрутов, как пеших, так и водных. Один из самых известных – маршрут на пик Черского (2090 м), который нам и предстояло преодолеть.

Маршрут считается «детским», некатегорийным, обычно проходится за 2 дня (первый день до базового лагеря, второй – на пик и назад), но есть варианты прохождения за день налегке или, наоборот, за большее количество дней. Мы, как не самые подготовленные туристы, решили пройти маршрут, не особо напрягаясь, за 4 дня, но справились за 3.

Маршрут начинается в Слюдянке, городке почти в самой южной точке Байкала. Едем туда на электричке из Иркутска или откуда-нибудь из другого места. Там заходим в магазин скупится в дорогу, короткий перекус – и в дорогу. Сначала нужно пройти через Слюдянку, километра четыре. Вскоре выходим из города и по "дороге из желтого кирпича" устремляемся в горы. Справа журчит река (тоже, как ни странно, Слюдянка), за ней и слева начинаются горы, пока еще невысокие. Река названа не просто так – здесь раньше добывали не только слюду, но и огромное количество минералов. Выходим на автодорогу и дальше идем по ней. Здесь главное не промахнутся и еще один раз сойти с дороги, чтобы не плутать по серпантину. Дорога плавно входит в лес, и дальше мы уже идем по нему. Слюдянка постоянно рядом с нами, по сути, мы находимся внутри ее каньона. Маршрут этот интересен тем, что дорога наша пересекает реку и ее притоки раз 20 и не везде есть мосты. То есть где-то в половине случаев нам придется переходить реку вброд. А это не так-то просто. Температура воды по ощущениям – градусов 5, и то, если есть. Когда выходишь из воды, хочется прыгать, так коченеют ноги. Впрочем, нам грех жаловаться – в наше появление воды в реке было относительно немного, обычно люди заходят по пояс, нам в этом плане повезло чуть больше. Переходить реку лучше в обуви, босиком опасно. Я, как самый недалекий, взял с собой шлепки, поэтому мне пришлось их привязывать резинками к ногам, чтобы не смыло. Течение здесь быстрое, того и гляди свалит человека, поэтому умыкнуть тапки для него – проще пареной репы.

Алгоритм прохода маршрута прост: подходим к реке, в надежде ищем мост, если находим мост, переходим по мосту, если не находим мост, переобуваемся из кроссовок в сандали/шлепки, переходим вброд, переобуваемся назад в кроссовки. Это поначалу. Переобуваться желательно, потому что в мокрой обуви себе, во-первых, можно натереть ноги, а, во-вторых, легко сорваться с камней. Однако уже через несколько итераций этого цикла начинаем смотреть на GPS, далеко ли следующий брод, и, если недалеко, то не переобуваемся. Потому что задалбывает. Так мы проходим километр за километром. Дорога у нас время от времени становится высохшим руслом речки. Весной здесь настоящие реки, летом они высыхают. Под ногами в основном большие камни с перерывами на нормальный грунт.

Через несколько часов справа появляется мраморная гора. На самом деле, гора искусственная. Выше метров на 100 находится карьер, а сюда самосвалы сбрасывают по склону камень. Любуемся горой, общаемся с проходящими мимо поляками, которые приветливо улыбаются, когда узнают, что мы из Украины. Отсюда, что Украина, что Польша, что Питер – одно и то же. По сравнению с 5000 км расстояние между Киевом и Варшавой кажется незначительным, поэтому мы с ними здесь почти земляки.

Идем дальше. На одном из бродов нас обгоняет небольшой УАЗик – только такие тут и ездят, наши городские «внедорожники» здесь почти полным составом могут разве что постоять на солнышке. Здесь есть место лишь для настоящих машин, а не для бесполезно жрущих топливо паркетных танков.

Еще через несколько километров выходим к базе отдыха. Группа деревянных домиков, беседка, пиво в импровизированном холодильнике и манящие остаться хозяева. У нас чай с собой, а впереди еще много километров, поэтому спасибо, мы идем дальше.

Поднимаемся все выше и выше. Высота уже около 1100-1200 метров. Пережидаем дождик, кушаем и идем дальше. Скоро заканчивается дорога и дальше начинается обычная лесная тропинка. Здесь леса становится резко больше. Решаем сегодня пройти хотя бы до Горелой поляны, это еще несколько километров. По пути нас еще раз мочит дождь. На поляне понимаем, что места для палаток здесь немного и решаем идти дальше. Смеркается. После дождя атмосфера невыносимая. Воздух холодеет, над рекой и мокрой землей начинает образовываться пар, пот течет ручьем, а мы все поднимаемся. Вскоре доходим до Казачьей поляны. Высота здесь – около 1400 метров, до Метеостанции остается 100 метров вверх и 400 метров по горизонтали. Находим отличное место на поляне и решаем заночевать здесь. Нам на метеостанцию спешить не нужно, а места там может уже и не быть. Наспех разбиваем палатки и готовим ужин.

По ходу дела мимо проходит еще один такой же, как и мы, турист из Питера. Знакомимся, приглашаем его на чай со сладеньким. Он принимает приглашение и скоро приходит со своим кипятком. Рассказывает нам, что только вернулся с группой из Хакасии, теперь вот сам хочет погулять по Хамар-Дабану, а потом у него по плану – путешествие на лошадях по Алтаю. Молодец, ничего не скажешь. Допиваем чай и ложимся спать. Сегодня мы проделали больше, чем собирались по плану, поэтому заслужили отдых. Как только залазим в палатки, начинается дождь. Вовремя.

Утром просыпаемся не слишком рано. Дождь закончился, солнце светит ярко и мы можем начинать собираться. Потихоньку сушим палатки, готовим завтрак. Вокруг снуют бурундуки, мы подкидываем им немного сухариков и хлеба и фотографируем. Бурундуки – это местные белки. Так же быстро и ловко лазят по деревьям, так же пугливы, но в то же время не гнушаются людского общества. Очень любят свистеть в случае опасности и безо всякого случая.Оставив зверькам солидный запас пищи, мы выдвигаемся в дорогу. Проходим до конца поляны и выходим на тропинку, ведущую наверх градусов под 60-70. Корни деревьев выпирают из земли, образуя своеобразную лестницу. Под ногами – ковер из хвои.

Шикарное место, жаль, что дорожка так быстро заканчивается. 100 метров вверх и вот мы снова выходим на ровную поверхность. Высота 1500 м. Нас встречает знак о том, что мы находимся на территории метеостанции, что здесь не стоит сорить, и вообще следует относиться к природе аккуратно. Чуть дальше видны домики метеостанции. Обычные деревянные домики. Рядом несколько флюгеров, несколько других приборов, сараи и колодец. В колодце вода привозная, поэтому рядом с колодцем тоже висит объявление о том, что возле него нельзя мыть посуду, купаться и вообще воды мало, так что будьте экономны.

Проходим мимо станции и идем дальше по поляне искать место для палаток. Слева и справа люди уже обосновались, хотя палаток не так много, как я ожидал. Вскоре находим хорошее место и разбиваем лагерь. Еще 12 часов дня и мы еще можем успеть сбегать на пик. Ставим палатки, берем в рюкзак самое необходимое, остальное забрасываем в палатки. Когда мы сюда шли, я думал, КАК это можно оставить вещи непонятно где и идти дальше. Теперь я понял: сюда различного рода асоциальные элементы просто не доходят, вокруг люди, которых мы видели вчера, стоят пустые палатки. Это нормально. Это нормальные люди, которые, как и ты, ничего чужого не возьмут, а наоборот разделят с тобой последний кусок хлеба, если понадобится. Выдвигаемся. Идти здесь очень приятно – вокруг уже не лиственный лес, а хвойный, здесь суше, земля каменистее. Поднимаемся по серпантину на хребет. Здесь главное не пропустить несколько поворотов. На одном есть указатель «Наверх», заботливо вывешенный кем-то, на другом, уже почти на самом хребте, где идет древняя почтовая дорога на Монголию, его нет, можно и промахнуться. Ну, ничего, зато можно сходить в Монголию :) По пути встречаем много людей, которые большими и маленькими группками поднимаются или спускаются с хребта. Со всеми здороваемся – здесь так принято. Выходим на хребет. Далеко позади, между двух хребтов, видна наша метеостанция. Отсюда открывается шикарный вид на окружающие горы во все стороны. Останавливаемся отдохнуть и полюбоваться.

Высота где-то около 1800 м. Здесь леса уже нет, вокруг луг, покрытый мхом и низкой растительностью. Много цветов, кедровый сланик, одинокие и невысокие деревья. Над головой вальяжно расхаживают крупные тучи и облачка поменьше. Внизу, в долинах, деревьев побольше, кое-где видны речки и небольшие озера. Перемахиваем через хребет и перед нами открывается пик Черского – потрясающая вершина, до которой нам еще топать пару километров через 2 перешейка.На первом находится памятник погибшей в 60х альпинистке, как напоминание всем гостям о том, что горы – это не игрушка, здесь опасно. Перешеек достаточно широкий, но слева и справа – обрывы, круто уходящие вниз. Здесь уже достаточно холодно, ветер пробирает. Поднимаемся на спутницу пика Черского, постоянно отмеряя высоту по GPS и очень скоро доходим до места, где стоят 3 каменные горки. По-видимому, это рубеж 2000 м. Сверяемся с нашим GPS – так и есть, мы сюда добрались! Идем выше, доходим до вершины и собираемся на второй перешеек, который ведет уже к пику. Люди идут туда с рюкзаками, но мы, осмотрев переход, решаем остановиться, потому что дальше идти страшновато. Потом, вечером, мы узнаем, что в этом году зимой было землетрясение, которое немного подпортило перешеек и теперь туда решаются идти далеко не все. Мы вот не решились. Зато за горой нам открывается удивительный вид на долину между горами, где находится озеро Сердце. Оно действительно имеет такую форму. Над озером пробегают облака и время замедляет свой бег. Мы находим камень побольше и садимся под его защитой со стороны пика и озера. Вид просто шикарнейший. Кушаем, фотографируем, общаемся. Высота около 2030 м.

Пока ты находишься в этом месте, рядом с одной из вершин Хамар-Дабана, рассматривая панораму гор вокруг и блеск озера в долине под ногами, ты думаешь о том, что вся наша обычная жизнь, по сути, суета сует. Все эти политические баталии, шум городов, войны не стоят и одной минуты здесь. Все мы – всего лишь крупинка на этой планете, наша жизнь по сравнению с жизнью этих гор – доля секунды. В своей заносчивости и гордыне мы думаем, что стали хозяевами Вселенной, что мы имеем право убивать редких животных ради наживы, уничтожать леса ради прибыли, засорять реки и океаны лишь просто потому что нам лень немного потрудиться и не допустить этого. А на деле мы всего лишь бабочки-однодневки, которых планета может стряхнуть с себя в любой момент, когда ей надоест наш произвол, наше потребительское отношение. Мы родимся и умрем, а эти горы, это небо, это солнце будут вечно. Они видели как менялись времена, как приходили и уходили эпохи, как появился человек, как эти земли осваивали монголы и те, кто был до них, как переселялись народы, как сюда добрались европейцы и объявили эти земли своими, они видели войны и революции, но сами они мало изменились за это время. И вот ради того, чтобы в очередной раз почувствовать эту вечность, эту мудрость, мысленно пообщаться с нею, люди и идут сюда, в Тибет, на Памир, в Гималаи или еще куда-нибудь, карабкаются на эти вершины, преодолевают снега и реки, преодолевают себя. А потом возвращаются назад, очищенные от суеты, с тем новым пониманием, которое они приобрели здесь. С надеждой, что человечество одумается и сможет повернуть повозку, летящую к краю пропасти, и спасти себя и окружающую природу.

Вот и пора возвращаться. Напоследок окидываем взором окрестности и с чувством почти выполненного долга начинаем наш путь назад. До самой метеостанции добираемся без приключений. Сейчас около 5 часов вечера, то есть мы справились где-то за 4-5 часов. Рядом с нашими двумя палатками появились гости – еще две палатки стоят без надзора, а их хозяева, как и мы, убежали осматривать окрестности. Мы решаем сходить на разведку на недавно появившуюся здесь «базу отдыха» и узнаем, что там можно искупаться. «Полцарства за коня!» - решаем мы, и идем купаться. Вернувшись, набираем воды в колодце и начинаем готовить ужин. Рядом с нами виднеется указатель на какой-то туалет. Идем на разведку – и вот он! На достаточно крутом склоне горы притаился сбитая из дерева открытая площадка с дырой посередине, занавешенная синей порванной во всех местах простыней. Зато какая романтика! Сидишь себе, осматриваешь окрестности :) Людей на метеостанции ощутимо прибавилось, так как сегодня суббота, самое время для людей приходить на пик. Только они, как правило, на пик только собираются, а мы уже оттуда. Пообщавшись с нашими новыми соседями, и девушкой, которая без проблем распознала в нас украинцев по акценту, идем спать. Засыпая, я думаю о том, что начинаю понимать людей, которые ходят в горы...

На следующее утро мы понимаем, что всю ночь лил дождь, а солнце не собирается нас радовать своим присутствием. Решаем, что нам это не важно, собираем мокрые палатки, завтракаем и выдвигаемся в обратную дорогу. Спуск по хвойной дорожке, Казачья поляна – и мы снова входим в царство леса. Вскоре справа появляется наша спутница Слюдянка. Без приключений доходим до начала дороги и понимаем, что мы еще успеем на последнюю электричку в полшестого. Берем ноги в руки и быстро-быстро идем на электричку. Кушаем на ходу, благо есть орешки и шоколад. Воду пьем прямо из реки.

Не переобуваемся – некогда. Ноги потихоньку натираются, но мы постоянно меняем пластыри и настырно спускаемся вниз, по пути постоянно проясняя свое положение по GPS и расстояние до вокзала. Уже где-то за 2 километра до начала деревни понимаем, что, если не случится чудо, мы не успеем, и нам придется ночевать на вокзале и уезжать утром. Но чудо все-таки случается, видимо, Хамар-Дабан решил нам сделать прощальный подарок перед расставанием. На дороге стоит водитель, который как раз закончил копаться в моторе и хочет уже уезжать в Слюдянку по своим делам. Андрей подходит к нему и просит за некоторую плату подвести нас до вокзала. Водитель соглашается, мы садимся в машину и трогаемся. Приди мы на 10 минут раньше – он бы еще возился с машиной и не повез бы нас. Опоздай мы хотя бы на пару минут – он бы уже уехал. До вокзала он нас домчал минут за 10, по пути цепляя неровности дороги из-за перегруза. Каждый треск и скрип под днищем мы воспринимаем как увеличение нашей платы за проезд :) На вокзале мы спрашиваем, сколько с нас, он отвечает: «сколько не жалко». У нас мелких денег не оказалось, поэтому нам «не жалко» 500 рублей. В конце-концов, он заслужил. На электричку мы успеваем. Слава Богу. Итого – 3 дня, около 60 км по горизонтали и 1500 м по вертикали. Куча впечатлений, воспоминаний и фотографий. Спасибо тебе, Хамар-Дабан, за прекрасную погоду, за это свидание с природой, за бездну положительных эмоций, за пик Черского и озеро Сердце. Это было незабываемо.

PS. Больше фотографий из похода можно глянуть в галерее.