Simple profiler

addewyd@

Member
Иногда не хватает такой простой вещи, как профайлер.

Поэтому накидал для себя такой скриптик

JavaScript:
const fs = require('fs')
const readline = require('readline');
const M = require('moment')
const iconv = require('iconv-lite');

if(process.argv.length < 3) {
    console.log('supply logfile as argument')
    process.exit(0)
}

const rl = readline.createInterface({
  input: fs.createReadStream(process.argv[2], 'binary'),
  output: null
});

rl.on('line', input => {
        handleline(input)
    })

rl.on('close', () => {
        handleclose()
    })

let scripttimes = {}
let steps = {}
let current_script = 'n/a'
let linecounter = 0;

let sc_sum = 0;
let st_sum = 0;

function handleline(str) {
    linecounter ++;

    let s = iconv.decode(Buffer.from(str, 'binary'), 'cp1251').toString();

    let as = s.split(/\s/)

    if(as.length < 3) return;
    if(!as[0].match(/^\d{4}/)) return;
    if(as[2] !== 'Info') return;

    let m;
    let dt = M(`${as[0]} ${as[1]}`, 'YYYY-MM-DD HH:mm:ss.SSSS')

    m = s.match(/Info --(Start|End) script \'(.+?)\*?\'/)
    if(m) {
        let sc = m[2]
        current_script = sc
        handlescript(sc, m[1], dt)
    } else {

        if(m = s.match(/ID: ([\-0-9a-z]+)/)) {
            let id = m[1];
            handlestep(s, id, dt)
        }
    }
}

function handlescript(sc, io, dt) {
    if(io == 'Start') {
        if(!scripttimes[sc]) {
            scripttimes[sc] = {}
        }
        scripttimes[sc].start = dt
        scripttimes[sc].sc = sc
        if(!scripttimes[sc].count) scripttimes[sc].count = 1;
        else scripttimes[sc].count ++;
    }

    if(io == 'End') {

        if(!scripttimes[sc]) {
            scripttimes[sc] = {}
        }

        if(!scripttimes[sc].start) scripttimes[sc].start = dt;
        if(!scripttimes[sc].sc) scripttimes[sc].sc = sc;

        scripttimes[sc].finish = dt;

        if(!scripttimes[sc].diff) scripttimes[sc].diff = 0;

        let diff = dt.diff(scripttimes[sc].start, 'milliseconds')
        scripttimes[sc].diff += diff
        sc_sum += diff;
        
    }
}

function handlestep(s, id, dt) {
    let m = s.match(/Executing step: \'(.+_?)\'/)
    if(!m) return;
    let step = m[1]

    let key = id + '-' + step

    if(s.match(/Info Start/)) {
        if(!steps[key]) {
            steps[key] = {}
        }
        steps[key].start = dt
        steps[key].step = step
        steps[key].id = id
        steps[key].script = current_script
        if(!steps[key].count) steps[key].count = 1;
        else steps[key].count ++;
    }

    if(s.match(/Info End/)) {
        if(!steps[key]) {
            steps[key] = {}
        }

        if(!steps[key].start) steps[key].start = dt;
        if(!steps[key].step) steps[key].step = step;
        if(!steps[key].id) steps[key].id = id;
        if(!steps[key].script) steps[key].script = current_script

        steps[key].finish = dt;

        if(!steps[key].diff) steps[key].diff = 0;
        let diff = dt.diff(steps[key].start, 'milliseconds')
        steps[key].diff += diff
        st_sum += diff
    }
}

function handleclose() {

    let s = []
    for(let k of Object.keys(scripttimes)) {
        let o = {name: scripttimes[k].sc, diff: scripttimes[k].diff / 1000, count:scripttimes[k].count}
        s.push(o)
    }
    s.sort( (a, b) => { return diffsorter(a, b) })
    console.table(s)
    console.log("Sum: " + msformat(sc_sum))
    let r = []
    for(let k of Object.keys(steps)) {
        let o = {name: steps[k].step, diff: steps[k].diff / 1000, count: steps[k].count, id: steps[k].id, script: steps[k].script}
        r.push(o)
    }

    r.sort( (a, b) => { return diffsorter(a, b) })
    console.table(r)
    console.log("Sum: " + msformat(st_sum))
}

function diffsorter(a, b) {
    if(a.diff > b.diff) return -1;
    if(a.diff < b.diff) return 1;
    return 0;
}

function msformat(t) {
    return M(t).format("hh:mm:ss.SSSS")
}
package.json:

JSON:
{
  "name": "loganalyze",
  "version": "1.0.0",
  "description": "",
  "main": "analyze.js",
  "scripts": {
    "test": "echo \"Error: no test specified\" && exit 1"
  },
  "author": "",
  "license": "ISC",
  "dependencies": {
    "iconv-lite": "^0.6.2",
    "moment": "^2.29.1"
  }
}
Requirements: nodejs

Install:

npm install

В качестве параметра принимает имя логфайла.

Возможно, кому-нибудь пригодится.

UPD: Не забывайте писать заголовки шагов.

УПД2: В планах оформить это дело в виде активности: на входе 2 даты, на выходе таблица.
 
Последнее редактирование:

Кирилл Серов

Administrator
Команда форума
Добрый день!

А можете чуть подробнее описать, на предмет чего анализируете логи?
 

addewyd@

Member
По всему логу суммируется время выполнения каждого шага.

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

Ах да, ещё не помешает колонка счётчика вызовов (собственно, добавил счётчики и суммарное время... неверное).

У нас тут сутками крутится и время выполнения каждого цикла обработки данных ограничено.
 
Последнее редактирование:

addewyd@

Member
А вот с вариантом на c# возникла неожиданная проблема. Даже не знаю, как сказать...

Коротко:
Convert.ToDateTime(DateTime.ParseExact($"{d} {t}.{ms}", "yyyy-MM-dd hh:mm:ss.ffff")

падает на абсолютно корректных строках.
Строка не распознана как действительное значение DateTime.

Корректность строки проверена до бита.

Иногда. Идёт всё нормально, потом ррраз... и поехало. и до конца лога.

2020-11-17 06:22:53.0633 тут нормально
2020-11-17 18:47:30.4514 а тут уже падает и до конца...

Может, кто-то сталкивался?

УПД: HH:mm:ss Sorry, туплю
 
Последнее редактирование:

addewyd@

Member
Вот, собственно.

Логи смотрит в стандартном месте (LocalApplicationData/PIX) в опциях уточняется, какие.

Дата по умолчанию сегодня.
 

Вложения

addewyd@

Member
Строго говоря, кодировка не едет. Это table to json у меня так изобразил кириллицу в утф8
Можно с таблицей иначе работать...

Да и с этимjson можно.

Javascript:

console.table(JSON.parse(result))


1606141404304.png


Где-то так....

Activities

Исходники тоже положу на место, но позже
 
Верх