How to identifying why Dompdf takes so long to render a document

[philharmonie]

Is there a way to measure somehow what exactly takes so long? I have a big PDF file but anyhow it should not take so long. I tried already to remove all external stuff (without effect) so now I search a solution to track the seconds in which the creator does what.

[RainerBielefeld]

We have some discussion concerning probably this issue at "Plugin Task2PDF: 'Print open Tasks' fails with timeout error message"

Error log lines at comment by "R. Bielefeld Created at: 05.07.2022 06:48 Updated at: 05.07.2022 07:03"

If necessary: what can we do to narrow down roots of the problem?

[philharmonie]

I get a PDF created every time, but it takes very long. Is it possible to log the steps done by the PDF creator to see what takes so long?3,2

[bsweeney]

You'd have to look at something like XDebug's profiling capabilities to get a sense of where Dompdf is spending it's time.

If you can post a sample of your document I'm happy to take a look.

If not already using the latest release with PHP8 can help quite a bit with performance.

[RainerBielefeld]

Source text of a not working task from here:

## Telefonnotiz  
|  Datum Zeit|  Ansprechpartner  | Tel,.: | Thema   |  Erledigungsstatus   | 
|----|----|----|----|----|
|    |   |    |    |    |    

Telefon-/Gesprächs-Notizen 2110L001    RLT Umkleidekabinen GS Osterfeld 10 
Daten
Thema / Status
Notizinhalt
<Datum>
<Gesprächspartner>
 <Telefonnummer>
<Thema>
Infokopie <Infokopie:>
<Erledigungsstatus>
<Telefonnotiz>
04.04.22
1&1 Freundin
 (721) 9607521
<Thema>
Infokopie <Infokopie:>
<Erledigungsstatus>
<Telefonnotiz>
09.02.22
1&1 Freundin
 (721) 9607521
Mobil-Daten
Infokopie <Infokopie:>
<Erledigungsstatus>
1&1 Daten-Flat LTE S Telefónica-Netz
    • Empfang Goslar Osterfeld10?
    • Ab 21.?

3. Februar 2022
Birgit Planitzer
 05321 704-464
Fernzugang
Infokopie <Infokopie:>
gestartet
  /  /  
Hat Stefan Ebbers informiert?  / P. Fragt sich nun erst mal schlau, meldet sich wieder /  
Erfahrung mit Fernzgängen?  /  /  
Möglichkeiten?  /  /  
 
20.10.21
Howatherm, Schoeppel
 +49 6782 9999-0
Klappen
Infokopie <Infokopie:>
<Erledigungsstatus>
Betätigung mit standard-Drehantrieben Welle rund / vierkant 10 … 20 mm möglich
28.04.22
Hömann
 05312644630 
<Thema>
Infokopie <Infokopie:>
<Erledigungsstatus>
Offene Fragen:
a) Mir fehlen noch Typenbezeichnungen
a1) Heizregisterpumpe   /  /  
a1.1) Zubringerpumpe?   / Para25-130/7-50/SC0V Wilo  Buderus 8738806741 /  
a2) Heizregister-Regelventil und Stellantrieb   /  /  
Ansonsten noch Klärungsbedarf:
b) Hydraulische Schaltung am Heizregister?  / ?? /  
c) Genaue Typenbezeichnung(en) und Artikelnummer(n)
   BUDERUS Regelgerät(e) (BC10?)  / habe ich nunweitgehend  /  
c1) Belegung der Anschlüsse (Fühler, Ventile, ...)   /  ??  /  
alt
d) Heizkörper im Raum?  / Ja /  
e) Fernzugriff?  / H. RuftBetreiber an ?? /  
f) Glykol?  / nein, da drinnen? /  
neu:
g) Bewegungsmelder? Licht an? VOC? 
h) Sonstiges: 
i) Zuordnung der anlagenteile zu BUDERUS-Protokoll?   /  /  
11.10.21
<Gesprächspartner>
 <Telefonnummer>

MSR: 
<Thema>
Infokopie <Infokopie:>
<Erledigungsstatus>
Drin oder Draußen   / Drinnen /  
Motoransteuerung: Details   / alles klar. Zusatzparametrierung nicht erforderlich, alles bereits Motor-Werksseitig erledigt / 
 FU vorhanden?  Anzeigen schon eingebaut?  / es gibt keine extra-Anzeige /  
Frostschutz Typ?  / Extralieferung /  
Drehmmomentvorgabe für WRG-Bypass?  / 10Nm
 /  
Montagemöglichkeiten Zu- und Ablufftfühler  / ?? /  
Empfehlung Bereifungsschutz:   / Temperaturfühler /  
Kabeleinführungen?  /Nein  /  
Montagemöglichkeiten Kanalfühler?  /  Nein /  
Verdrahtungsplan K3G355PH4905 / Parametrierung: Klemmleistenbedeutung?
 Anschlüsse von wo nach wo?  / Zwischen Klemmbrett und Motor /    0-10V? /  / 
 Volumenstrommesssystem  / ?? /  
  Wie bekommen wir Volumenstromanzeige?   / Einfach parallelabgreifen /  
   Betrieb   /  /  Störung  /  /  
  /  /  


|   <Datum>
<Gesprächspartner>
 <Telefonnummer> |  b  | c   |    |  



Telefonnotiz  
|  A | B   | C   | C   |  



|----|----|----|----|
|   a |  b  | c   |    |  
|   a |  |  A | B   | C   | C   |  
|----|----|----|----|
|   a |  b  | c   |    |  
|   a |  b  | c   |    |    | c   |    |  
|   a |  b  | c   |    |  
|   a |  b  | c   |    |  

| Syntax | Description |  
| --- | ----------- |  
| Header | Title |  
| Paragraph | Text | 

[bsweeney]

I mean, as a template that doesn't look like something that would be problematic to render. But it doesn't really help debug any issues since there's no HTML to test against.

If you strip out references to external resources (images, CSS) does the document render faster?

[RainerBielefeld]

@bsweeney:
I don't understand your desire.

Would it help if you do a first test in my test environment?

This might help to find a solution how to create a testcase for you.

Here you can register.

Please send a notification here when you have registered so that I can grant access.

[bsweeney]

@RainerBielefeld are you saying that page itself is slow to render? I didn't see a "print to PDF" function so I thought it was just a bug report for the problem, not the actual problematic page.

[bsweeney]

@RainerBielefeld it looks like the nested custom elements (datum, gespr, infokopie, etc) are causing the rendering issues. While the original request in this issue can help identify where things are breaking with your document your problem is a little more specific to your document structure. I suggest you open a new issue.

[RainerBielefeld]

@bsweeney
Please simply register for the test environment as requested.
Then you have the possibility to do your own experiments concerning elements causing the problem and with that experience perhaps create your own debug tools

[philharmonie]

I don't see any relationship to my issue. Do I miss something?

[bsweeney]

So tracking the timing of individual elements is ... hard? Dompdf doesn't provide a lot of hooks into it's internal process. Something that can help here are render-time callbacks. With that you can check how long it's taking to render each frame.

$dompdf = new Dompdf();
$dompdf->loadHtml('...');

$performance = [];
$dompdf->setCallbacks(
    [
        [
            'event' => 'begin_frame',
            'f' => function ($frame, $canvas, $fontMetrics) use (&$performance) {
                $performance[$frame->get_id()] = [
                    'id' => $frame->get_id(),
                    'parent' => $frame->get_parent()->get_id(),
                    'rendertime' => hrtime(true),
                    'el' => $frame->get_node()->nodeName,
                    'text' => substr($frame->get_node()->nodeValue, 0, 100)
                ];
                error_log("starting {$frame->get_id()} {$frame->get_node()->nodeName}");
            }
        ],
        [
            'event' => 'end_frame',
            'f' => function ($frame, $canvas, $fontMetrics) use (&$performance) {
                $performance[$frame->get_id()]['rendertime'] = hrtime(true) - $performance[$frame->get_id()]['rendertime'];
                $time = $performance[$frame->get_id()]['rendertime']/1000000;
                error_log("ending {$frame->get_id()} {$time}ms");
            }
        ]
    ]
);
$dompdf->render();

I'm logging some output there, but also capturing data in an array so I can do some stuff post-render to try and figure out where things are slowing down. For a simple document you could just reverse sort the array and get the elements that took the longest time to render:

$performance_results = array_map(
    function ($val) {
        $val['rendertime'] = $val['rendertime'] / 1000000;
        return $val;
    },
    $performance
);
usort(
    $performance_results,
    function ($a, $b) {
        if ($a['rendertime'] == $b['rendertime']) {
            return 0;
        }
        return ($a['rendertime'] < $b['rendertime']) ? 1 : -1; // reverse sort
    }
);
$info = current($performance_results);
for ($i = 0; $i < 10; $i++) {
    print_r($info);
    $info = next($performance_results);
}

Of course, parent frame render time will encompass all it's children so just doing a reverse sort is probably not sufficient for normal-use cases. You could do something more advanced like generate a tree view using logic similar to what's offered here: https://stackoverflow.com/a/2915920/264628 (along with a little HTML5 magic).

function parseTree($tree, $root = null) {
    $return = array();
    # Traverse the tree and search for direct children of the root
    foreach ($tree as $id => $info) {
        # A direct child is found
        if ($info['parent'] == $root) {
            # Remove item from tree (we don't need to traverse this again)
            unset($tree[$id]);
            # Append the child into result array and parse its children
            $return[] = array(
                'id' => $id,
                'info' => $info,
                'children' => parseTree($tree, $id)
            );
        }
    }
    return empty($return) ? null : $return;
}
function printTree($tree) {
    if (!is_null($tree) && count($tree) > 0) {
        echo '<div style="margin-left: 1.5em;">';
        foreach ($tree as $node) {
            $time = $node['info']['rendertime']/1000000;
            echo "<details><summary>{$node['info']['el']} {$time}ms ({$node['info']['text']})</summary>";
            printTree($node['children']);
            echo '</details>';
        }
        echo '</div>';
    }
}
ob_start();
$perf_tree = parseTree($performance);
printTree($perf_tree);
$perf_tree_html = ob_get_contents();
ob_end_clean();
file_put_contents('perf.html', $perf_tree_html);

This won't capture time spent doing things like parsing the document and applying styles to each frame. One thing that can slow down document rendering is if you have a lot of frames. Large documents won't necessarily be slow, but if there's a lot of elements to parse that can take a while.

[bsweeney]

If you think your performance issues might be impacted by a large number of nested inline frames #2949 should address the issue.