Тормозит создание буфера.

[Logger]

Привет всем.
Обнаружил неприятную особенность виртуальных компаний.
Если табличка включена в виртуальную компанию то создание буфера может тормозить и занимать гигантское время (у нас до 1,2 миллисекунд).
Неважно каким способом создавать буфер.
common.data() // дублирование
dictTable.MakeRecord()
map.lookup() // достаем из мапа
conPeek(con, 1) // достаем из контейнера

Важно условие - длительность тормозов прямо зависит от числа компаний в системе (примерно линейная зависимость наблюдается). У нас 280 компаний - для такого количества порядка 1 миллисекунды торможение. Казалось бы немного но при работе с разными выгрузками когда обрабатываются десятки тысяч записей эти миллисекунды превращаются в минуты.

Интересно, что если буфер создавать в компании dat, которая не включена в виртуальную компанию, то все быстро. Т.е. глюк проявляется в зависимости от того в какой компании создается буфер.

Обнаружили случайно - была выгрузка остатков, которая в цикле перебирала мап из 20 тысяч элементов, на каждом шаге дочитывала настроечную табличку из 5 записей из БД. Решили оптимизировать - положили эти 5 записей в мап и стали брать из мапа, а оно стало медленнее работать раза в 2
Оказалось, что в наших условиях запрос к БД длился 0,5 миллисекунд, а создание нового буфера (при доставании из мапа) длилось 1,2 миллисекунды, что привело к замедление выгрузки секунд на 30.

Как можно это обойти:
1. Выкинуть буфер из виртуальной компании. (отключить saveDataPercompany для него и создать свое кастомизированное поле с кодом компании)
или
2. Постараться изменить код чтобы часто не создавать табличный буфер.
или
3. Если надо хранить данные буфера в мапе или другому подобном хранилище, то меняем мап с хранения табличных буферов на контейнеры и реализуем на буфере методы pack и unpack и работаем с буфером дальше. Только в процессе работы экземпляр таблички не пересоздаем а вызываем на нем unpack передавая в аргументы контейнер который достали из мапа.

P.S.
Проверял все на версии 2009 (воспроизводится на билдах ядра 1600.3596 и 1500.4570 (RU7))

[Logger]

Вот набросал джобик для проверки

static void Job3798_3(Args _args)
{
    VirtualDataAreaList     virtualDataAreaList;
    Dataarea                Dataarea;
    int                     tick1;
    int                     tick2;
    int                     i;
    DictTable               dictTable;
    common                  common;
    common                  common2;
    container               contable =

//        [tableNum(LEDGERJOURNALPOSTCONTROLUSERGROUP), "100"] // time 0,19     steps 20000  table   LedgerJournalPostControlUserGroup (company = 100)
//        [tableNum(LEDGERJOURNALPOSTCONTROLUSERGROUP), "dat"] // time 0,17     steps 20000  table   LedgerJournalPostControlUserGroup (company = dat)

//        [tableNum(LEDGERBALANCESHEETDIMFILEFORMAT), "100"] // time 0,17     steps 20000  table   LedgerBalanceSheetDimFileFormat (company = 100)
//        [tableNum(LEDGERBALANCESHEETDIMFILEFORMAT), "dat"] // time 0,19     steps 20000  table   LedgerBalanceSheetDimFileFormat (company = dat)

//        [tableNum(SalesTable), "100"] // time 0,25     steps 20000  table   SalesTable (company = 100)
//        [tableNum(SalesTable), "dat"] // time 0,25     steps 20000  table   SalesTable (company = dat)

//        [tableNum(DIRPARTYADDRESSRELATIONSHIPMAPPING), "100"] // time 10,25     steps 20000  table   DirPartyAddressRelationshipMapping (company = gab)  win2003    - CPU 2,6 GHz
                                                                // time 18,55     steps 20000  table   DirPartyAddressRelationshipMapping (company = gab)  win2008 R2 - CPU 2,3 GHz
//        [tableNum(DIRPARTYADDRESSRELATIONSHIPMAPPING), "dat"]   // time 10,19     steps 20000  table   DirPartyAddressRelationshipMapping (company = gab)
                                                                // time 19,73     steps 20000  table   DirPartyAddressRelationshipMapping (company = gab)  win2008 R2

//        [tableNum(CustTable), "100"] // time 10,08     steps 20000  table   CustTable (company = hld) - win2003
                                     // time 0,22     steps 20000  table   CustTable (company = dat) - win2008 R2
//        [tableNum(CustTable), "dat"] // time 0,22     steps 20000  table   CustTable (company = dat)

//        [tableNum(SysUserLog), "100"] // time 0,20     steps 20000  table   SysUserLog (company = No savePerCompany) - win2008 R2
//        [tableNum(SysUserLog), "dat"] // time 0,19     steps 20000  table   SysUserLog (company = No savePerCompany)  - win2008 R2


        [tableNum(GRD_SpecialDeptsInventLocations), "100"] // time 14,02     steps 20000  table   GRD_SpecialDeptsInventLocations (company = msc) for win2003
                                                           // time 27,16     steps 20000  table   GRD_SpecialDeptsInventLocations (company = msc) for win2008 R2

//        [tableNum(GRD_SpecialDeptsInventLocations), "dat"] // time 0,16     steps 20000  table   GRD_SpecialDeptsInventLocations (company = dat)  for win2003
                                                           // time 0,19     steps 20000  table   GRD_SpecialDeptsInventLocations (company = dat)  for win2008 R2
        ;

    ;
    appl.setDefaultCompany(conPeek(contable, 2));
    dictTable = new SysDictTable(conPeek(contable, 1));
    common = dictTable.makeRecord();
    common.(fieldNum(common, recid)) = 123; // force kernel to create a buffer instance

    select count(recId) from Dataarea where Dataarea.isVirtual;
    info(strFMT("count VirtCompanies = %1", Dataarea.RecId));

    select count(recId) from Dataarea where !Dataarea.isVirtual;
    info(strFMT("count Companies = %1", Dataarea.RecId));

    if (!dictTable.dataPrCompany())
    {
        info("Not percompany table");
    }
    else
    if (xDataarea::find(common.dataAreaId).isVirtual)
    {
        select count(recid) from virtualDataAreaList where virtualDataAreaList.virtualDataArea == common.dataAreaId;
        info(strFMT("table %1  contains  %2  companies for virtual %3", dictTable.name(), virtualDataAreaList.RecId, common.dataAreaId));
    }
    else
    {
        info(strFMT("table %1 is not virtual for company %2", dictTable.name(), common.dataAreaId));
    }

    tick1 = WinApi::getTickCount();
    i = 0;

    for (i = 1; i < 20000; i++)
    {
        common2 = common.data(); // make a buffer copy
        // also runs slowly with :
        // common2 = conpeek(con, 1);
        // common2 = map.lookup(1);
        // every time you create an instance of buffer
    }
    tick2 = WinApi::getTickCount();
    info(strFMT(
        "time %1     steps %2  table   %3 (company = %4)",
        (tick2-tick1)/1000,
        i,
        dictTable.name(),
        dictTable.dataPrCompany() ? common.dataAreaId : "No savePerCompany"
        ));

}

[DSPIC]

Попробуйте по-трейспарсить?

[Logger]

Цитата:

Сообщение от DSPIC

Попробуйте по-трейспарсить?

Думаете я этого не делал ?
Джоб, это выжимка чтобы удобнее проиллюстрировать багу.

[Logger]

К слову, о трейспарсере. Cразу забыл написать о его баге, а тут еще по джобу замерял, чтобы точно никакие сторонние эффекты не влияли.

Как выяснилось хваленный trace parcer нам врет. Он не всегда корректно показывает Exclusive time и Inclusive time.

Пример трейса кода:


видно, что если просуммировать время указанное trace parcer - нигде мы не получим даже 0,2 миллисекунды, а реально там каждый шаг цикла длился 1-1,5 миллисекунды. Т.е. какие-то действия он не фиксирует и на них тратится существенное время.
Как это поймать ?
Выделяем строку в трейсе, потом щелкаем правой кнопкой мыши по другой строке - во всплывающем меню он предложит нам вывести время между событиями. Вот оно корректно отображается. В нашем случае 1,37 миллисекунды.

[Logger]

А вот я джобик замерял.
Это медленный вариант - в рабочей компании.


А это быстрый - в компании dat которая не включена в виртуальные.


трейсы внешне одинаковые.

Только в одном случае джоб выполнил 20 тысяч циклов за 25 секунд, а в другом за 0,5 секунды.

Так что trace parcer-у тоже верить нельзя. Все надо перепроверять.