tests/xmark_small.xml.summary

   1 Query: A1 : /site/closed_auctions/closed_auction/annotation/description/text/keyword
   2 STATS: parsing xml document: 634.769201ms
   3 STATS: parsing XPath query: 0.095844ms
   4 STATS: compiling XPath query: 0.281096ms
   5 STATS: Query: /child::site/child::closed_auctions/child::closed_auction/child::annotation/child::description/child::text/child::keyword
   6 STATS: Automaton:
   7 STATS: 254301 nodes over 254301 were skipped in iteration 0 (100.00 %), redo is: false
   8 STATS: evaluating query: 119.843006ms
   9 STATS: serializing results: 3.608942ms
  10 STATS: 254301 nodes over 254301 were skipped in iteration 1 (100.00 %), redo is: false
  11 STATS: 1 iterations
  12 STATS: automaton 0, cache2: 170 entries, cache6: 3149 entries
  13 STATS: cache2: length: 255, used: 85, occupation: 0.333333
  14 STATS: cache4: length: 3464, used: 315, occupation: 0.090935
  15 Diff: ok
  16 -------------------------------------------
  17 Query: A2 : //closed_auction//keyword
  18 STATS: parsing xml document: 191.257000ms
  19 STATS: parsing XPath query: 0.056028ms
  20 STATS: compiling XPath query: 0.144005ms
  21 STATS: Query: /descendant-or-self::node()/child::closed_auction/descendant-or-self::node()/child::keyword
  22 STATS: Automaton:
  23 STATS: 254301 nodes over 254301 were skipped in iteration 0 (100.00 %), redo is: false
  24 STATS: evaluating query: 130.471945ms
  25 STATS: serializing results: 6.496906ms
  26 STATS: 254301 nodes over 254301 were skipped in iteration 1 (100.00 %), redo is: false
  27 STATS: 1 iterations
  28 STATS: automaton 0, cache2: 170 entries, cache6: 2681 entries
  29 STATS: cache2: length: 255, used: 85, occupation: 0.333333
  30 STATS: cache4: length: 2915, used: 234, occupation: 0.080274
  31 Diff: ok
  32 -------------------------------------------
  33 Query: A3 : /site/closed_auctions/closed_auction//keyword
  34 STATS: parsing xml document: 189.831018ms
  35 STATS: parsing XPath query: 0.063896ms
  36 STATS: compiling XPath query: 0.157118ms
  37 STATS: Query: /child::site/child::closed_auctions/child::closed_auction/descendant-or-self::node()/child::keyword
  38 STATS: Automaton:
  39 STATS: 254301 nodes over 254301 were skipped in iteration 0 (100.00 %), redo is: false
  40 STATS: evaluating query: 139.882088ms
  41 STATS: serializing results: 6.744862ms
  42 STATS: 254301 nodes over 254301 were skipped in iteration 1 (100.00 %), redo is: false
  43 STATS: 1 iterations
  44 STATS: automaton 0, cache2: 170 entries, cache6: 3277 entries
  45 STATS: cache2: length: 255, used: 85, occupation: 0.333333
  46 STATS: cache4: length: 3555, used: 278, occupation: 0.078200
  47 Diff: ok
  48 -------------------------------------------
  49 Query: A4 : /site/closed_auctions/closed_auction[annotation/description/text/keyword]/date
  50 STATS: parsing xml document: 189.064026ms
  51 STATS: parsing XPath query: 0.106096ms
  52 STATS: compiling XPath query: 0.199080ms
  53 STATS: Query: /child::site/child::closed_auctions/child::closed_auction[ child::annotation/child::description/child::text/child::keyword ]/child::date
  54 STATS: Automaton:
  55 STATS: 245034 nodes over 254301 were skipped in iteration 0 (96.36 %), redo is: true
  56 STATS: 254301 nodes over 254301 were skipped in iteration 1 (100.00 %), redo is: false
  57 STATS: evaluating query: 135.497093ms
  58 STATS: serializing results: 2.182007ms
  59 STATS: 254301 nodes over 254301 were skipped in iteration 2 (100.00 %), redo is: false
  60 STATS: 2 iterations
  61 STATS: automaton 0, cache2: 0 entries, cache6: 282 entries
  62 STATS: cache2: length: 0, used: 0, occupation: -nan
  63 STATS: cache4: length: 355, used: 73, occupation: 0.205634
  64 Diff: ok
  65 -------------------------------------------
  66 Query: A5 : /site/closed_auctions/closed_auction[descendant::keyword]/date
  67 STATS: parsing xml document: 190.711021ms
  68 STATS: parsing XPath query: 0.084162ms
  69 STATS: compiling XPath query: 0.134945ms
  70 STATS: Query: /child::site/child::closed_auctions/child::closed_auction[ descendant::keyword ]/child::date
  71 STATS: Automaton:
  72 STATS: 245034 nodes over 254301 were skipped in iteration 0 (96.36 %), redo is: true
  73 STATS: 254301 nodes over 254301 were skipped in iteration 1 (100.00 %), redo is: false
  74 STATS: evaluating query: 138.205051ms
  75 STATS: serializing results: 2.486944ms
  76 STATS: 254301 nodes over 254301 were skipped in iteration 2 (100.00 %), redo is: false
  77 STATS: 2 iterations
  78 STATS: automaton 0, cache2: 0 entries, cache6: 259 entries
  79 STATS: cache2: length: 0, used: 0, occupation: -nan
  80 STATS: cache4: length: 342, used: 83, occupation: 0.242690
  81 Diff: ok
  82 -------------------------------------------
  83 Query: A6 : /site/people/person[profile/gender and profile/age]/name
  84 STATS: parsing xml document: 185.791016ms
  85 STATS: parsing XPath query: 0.102043ms
  86 STATS: compiling XPath query: 0.155210ms
  87 STATS: Query: /child::site/child::people/child::person[ child::profile/child::gender and child::profile/child::age ]/child::name
  88 STATS: Automaton:
  89 STATS: 236309 nodes over 254301 were skipped in iteration 0 (92.92 %), redo is: true
  90 STATS: 254301 nodes over 254301 were skipped in iteration 1 (100.00 %), redo is: false
  91 STATS: evaluating query: 149.569035ms
  92 STATS: serializing results: 2.363920ms
  93 STATS: 254301 nodes over 254301 were skipped in iteration 2 (100.00 %), redo is: false
  94 STATS: 2 iterations
  95 STATS: automaton 0, cache2: 0 entries, cache6: 1570 entries
  96 STATS: cache2: length: 0, used: 0, occupation: -nan
  97 STATS: cache4: length: 1719, used: 149, occupation: 0.086678
  98 Diff: ok
  99 -------------------------------------------
 100 Query: A7 : /site/people/person[phone or homepage]/name
 101 STATS: parsing xml document: 187.725067ms
 102 STATS: parsing XPath query: 0.087023ms
 103 STATS: compiling XPath query: 0.158072ms
 104 STATS: Query: /child::site/child::people/child::person[ child::phone or child::homepage ]/child::name
 105 STATS: Automaton:
 106 STATS: 236309 nodes over 254301 were skipped in iteration 0 (92.92 %), redo is: true
 107 STATS: 254301 nodes over 254301 were skipped in iteration 1 (100.00 %), redo is: false
 108 STATS: evaluating query: 140.325069ms
 109 STATS: serializing results: 4.892111ms
 110 STATS: 254301 nodes over 254301 were skipped in iteration 2 (100.00 %), redo is: false
 111 STATS: 2 iterations
 112 STATS: automaton 0, cache2: 0 entries, cache6: 1257 entries
 113 STATS: cache2: length: 0, used: 0, occupation: -nan
 114 STATS: cache4: length: 1420, used: 163, occupation: 0.114789
 115 Diff: ok
 116 -------------------------------------------
 117 Query: A8 : /site/people/person[address and (phone or homepage) and (creditcard or profile)]/name
 118 STATS: parsing xml document: 186.979055ms
 119 STATS: parsing XPath query: 0.118971ms
 120 STATS: compiling XPath query: 0.159979ms
 121 STATS: Query: /child::site/child::people/child::person[ child::address and (child::phone or child::homepage) and (child::creditcard or child::profile) ]/child::name
 122 STATS: Automaton:
 123 STATS: 236309 nodes over 254301 were skipped in iteration 0 (92.92 %), redo is: true
 124 STATS: 254301 nodes over 254301 were skipped in iteration 1 (100.00 %), redo is: false
 125 STATS: evaluating query: 150.840998ms
 126 STATS: serializing results: 3.206968ms
 127 STATS: 254301 nodes over 254301 were skipped in iteration 2 (100.00 %), redo is: false
 128 STATS: 2 iterations
 129 STATS: automaton 0, cache2: 0 entries, cache6: 7979 entries
 130 STATS: cache2: length: 0, used: 0, occupation: -nan
 131 STATS: cache4: length: 8812, used: 833, occupation: 0.094530
 132 Diff: ok
 133 -------------------------------------------
 134 Query: B1 : /site/regions/*/item[parent::namerica or parent::samerica]/name
 135 STATS: parsing xml document: 191.373110ms
 136 STATS: parsing XPath query: 0.096083ms
 137 STATS: compiling XPath query: 0.161171ms
 138 STATS: Query: /child::site/child::regions/child::*/child::item[ parent::namerica or parent::samerica ]/child::name
 139 STATS: Automaton:
 140 STATS: 254301 nodes over 254301 were skipped in iteration 0 (100.00 %), redo is: false
 141 STATS: evaluating query: 119.151115ms
 142 STATS: serializing results: 3.636837ms
 143 STATS: 254301 nodes over 254301 were skipped in iteration 1 (100.00 %), redo is: false
 144 STATS: 1 iterations
 145 STATS: automaton 0, cache2: 170 entries, cache6: 3466 entries
 146 STATS: cache2: length: 255, used: 85, occupation: 0.333333
 147 STATS: cache4: length: 3760, used: 294, occupation: 0.078191
 148 Diff: ok
 149 -------------------------------------------
 150 Query: B2 : //keyword/ancestor::listitem/text/keyword
 151 STATS: parsing xml document: 191.718102ms
 152 STATS: parsing XPath query: 0.073195ms
 153 STATS: compiling XPath query: 0.213861ms
 154 STATS: Query: /descendant-or-self::node()/child::keyword/ancestor::listitem/child::text/child::keyword
 155 STATS: Automaton:
 156 STATS: 210583 nodes over 254301 were skipped in iteration 0 (82.81 %), redo is: true
 157 STATS: 254301 nodes over 254301 were skipped in iteration 1 (100.00 %), redo is: false
 158 STATS: evaluating query: 166.561127ms
 159 STATS: serializing results: 13.072968ms
 160 STATS: 254301 nodes over 254301 were skipped in iteration 2 (100.00 %), redo is: false
 161 STATS: 2 iterations
 162 STATS: automaton 0, cache2: 0 entries, cache6: 1811 entries
 163 STATS: cache2: length: 0, used: 0, occupation: -nan
 164 STATS: cache4: length: 2050, used: 239, occupation: 0.116585
 165 Diff: ok
 166 -------------------------------------------
 167 Query: B3 : /site/open_auctions/open_auction/bidder[following-sibling::bidder]
 168 STATS: parsing xml document: 191.766024ms
 169 STATS: parsing XPath query: 0.077009ms
 170 STATS: compiling XPath query: 0.133991ms
 171 STATS: Query: /child::site/child::open_auctions/child::open_auction/child::bidder[ following-sibling::bidder ]
 172 STATS: Automaton:
 173 STATS: 254301 nodes over 254301 were skipped in iteration 0 (100.00 %), redo is: false
 174 STATS: evaluating query: 130.250931ms
 175 STATS: serializing results: 31.550884ms
 176 STATS: 254301 nodes over 254301 were skipped in iteration 1 (100.00 %), redo is: false
 177 STATS: 1 iterations
 178 STATS: automaton 0, cache2: 170 entries, cache6: 2871 entries
 179 STATS: cache2: length: 255, used: 85, occupation: 0.333333
 180 STATS: cache4: length: 3131, used: 260, occupation: 0.083041
 181 Diff: ok
 182 -------------------------------------------
 183 Query: B4 : /site/open_auctions/open_auction/bidder[preceding-sibling::bidder]
 184 STATS: parsing xml document: 189.858913ms
 185 STATS: parsing XPath query: 0.082970ms
 186 STATS: compiling XPath query: 0.122070ms
 187 STATS: Query: /child::site/child::open_auctions/child::open_auction/child::bidder[ preceding-sibling::bidder ]
 188 STATS: Automaton:
 189 STATS: 254301 nodes over 254301 were skipped in iteration 0 (100.00 %), redo is: false
 190 STATS: evaluating query: 117.531061ms
 191 STATS: serializing results: 31.703949ms
 192 STATS: 254301 nodes over 254301 were skipped in iteration 1 (100.00 %), redo is: false
 193 STATS: 1 iterations
 194 STATS: automaton 0, cache2: 170 entries, cache6: 2282 entries
 195 STATS: cache2: length: 255, used: 85, occupation: 0.333333
 196 STATS: cache4: length: 2507, used: 225, occupation: 0.089749
 197 Diff: ok
 198 -------------------------------------------
 199 Query: B5 : /site/regions/*/item[following::item]/name
 200 STATS: parsing xml document: 186.423779ms
 201 STATS: parsing XPath query: 0.076056ms
 202 STATS: compiling XPath query: 0.211000ms
 203 STATS: Query: /child::site/child::regions/child::*/child::item[ ancestor-or-self::node()/following-sibling::node()/descendant-or-self::item ]/child::name
 204 STATS: Automaton:
 205 STATS: 1 nodes over 254301 were skipped in iteration 0 (0.00 %), redo is: true
 206 STATS: 254301 nodes over 254301 were skipped in iteration 1 (100.00 %), redo is: false
 207 STATS: evaluating query: 200.829983ms
 208 STATS: serializing results: 5.727053ms
 209 STATS: 254301 nodes over 254301 were skipped in iteration 2 (100.00 %), redo is: false
 210 STATS: 2 iterations
 211 STATS: automaton 0, cache2: 0 entries, cache6: 1990 entries
 212 STATS: cache2: length: 0, used: 0, occupation: -nan
 213 STATS: cache4: length: 2299, used: 309, occupation: 0.134406
 214 Diff: ok
 215 -------------------------------------------
 216 Query: B6 : /site/regions/*/item[preceding::item]/name
 217 STATS: parsing xml document: 187.946081ms
 218 STATS: parsing XPath query: 0.046968ms
 219 STATS: compiling XPath query: 0.171900ms
 220 STATS: Query: /child::site/child::regions/child::*/child::item[ ancestor-or-self::node()/preceding-sibling::node()/descendant-or-self::item ]/child::name
 221 STATS: Automaton:
 222 STATS: 254301 nodes over 254301 were skipped in iteration 0 (100.00 %), redo is: false
 223 STATS: evaluating query: 140.237093ms
 224 STATS: serializing results: 5.573988ms
 225 STATS: 254301 nodes over 254301 were skipped in iteration 1 (100.00 %), redo is: false
 226 STATS: 1 iterations
 227 STATS: automaton 0, cache2: 170 entries, cache6: 4419 entries
 228 STATS: cache2: length: 255, used: 85, occupation: 0.333333
 229 STATS: cache4: length: 4800, used: 381, occupation: 0.079375
 230 Diff: ok
 231 -------------------------------------------
 232 Query: B7 : //person[profile/@income]/name
 233 STATS: parsing xml document: 192.195177ms
 234 STATS: parsing XPath query: 0.074148ms
 235 STATS: compiling XPath query: 0.116110ms
 236 STATS: Query: /descendant-or-self::node()/child::person[ child::profile/attribute::@income ]/child::name
 237 STATS: Automaton:
 238 STATS: 236309 nodes over 254301 were skipped in iteration 0 (92.92 %), redo is: true
 239 STATS: 254301 nodes over 254301 were skipped in iteration 1 (100.00 %), redo is: false
 240 STATS: evaluating query: 145.928860ms
 241 STATS: serializing results: 4.064083ms
 242 STATS: 254301 nodes over 254301 were skipped in iteration 2 (100.00 %), redo is: false
 243 STATS: 2 iterations
 244 STATS: automaton 0, cache2: 0 entries, cache6: 624 entries
 245 STATS: cache2: length: 0, used: 0, occupation: -nan
 246 STATS: cache4: length: 705, used: 81, occupation: 0.114894
 247 Diff: ok
 248 -------------------------------------------
 249 Query: B8 : /site/open_auctions/open_auction[bidder and not(bidder/preceding-sibling::bidder)]/interval
 250 STATS: parsing xml document: 189.630985ms
 251 STATS: parsing XPath query: 0.108004ms
 252 STATS: compiling XPath query: 0.137091ms
 253 STATS: Query: /child::site/child::open_auctions/child::open_auction[ child::bidder and not(child::bidder/preceding-sibling::bidder) ]/child::interval
 254 STATS: Automaton:
 255 STATS: 235063 nodes over 254301 were skipped in iteration 0 (92.43 %), redo is: true
 256 STATS: 254301 nodes over 254301 were skipped in iteration 1 (100.00 %), redo is: false
 257 STATS: evaluating query: 140.723944ms
 258 STATS: serializing results: 2.576828ms
 259 STATS: 254301 nodes over 254301 were skipped in iteration 2 (100.00 %), redo is: false
 260 STATS: 2 iterations
 261 STATS: automaton 0, cache2: 0 entries, cache6: 368 entries
 262 STATS: cache2: length: 0, used: 0, occupation: -nan
 263 STATS: cache4: length: 506, used: 138, occupation: 0.272727
 264 Diff: ok
 265 -------------------------------------------
 266 Query: B9 : /site/open_auctions/open_auction[(not(bidder/following::bidder) or not(bidder/preceding::bidder)) or (bidder/following::bidder and bidder/preceding::bidder)]/interval
 267 STATS: parsing xml document: 180.969000ms
 268 STATS: parsing XPath query: 0.151157ms
 269 STATS: compiling XPath query: 0.355959ms
 270 STATS: Query: /child::site/child::open_auctions/child::open_auction[ not(child::bidder/ancestor-or-self::node()/following-sibling::node()/descendant-or-self::bidder) or not(child::bidder/ancestor-or-self::node()/preceding-sibling::node()/descendant-or-self::bidder) or child::bidder/ancestor-or-self::node()/following-sibling::node()/descendant-or-self::bidder and child::bidder/ancestor-or-self::node()/preceding-sibling::node()/descendant-or-self::bidder ]/child::interval
 271 STATS: Automaton:
 272 STATS: 1 nodes over 254301 were skipped in iteration 0 (0.00 %), redo is: true
 273 STATS: 251143 nodes over 254301 were skipped in iteration 1 (98.76 %), redo is: true
 274 STATS: 254301 nodes over 254301 were skipped in iteration 2 (100.00 %), redo is: false
 275 STATS: evaluating query: 224.873066ms
 276 STATS: serializing results: 6.433010ms
 277 STATS: 254301 nodes over 254301 were skipped in iteration 3 (100.00 %), redo is: false
 278 STATS: 3 iterations
 279 STATS: automaton 0, cache2: 0 entries, cache6: 157 entries
 280 STATS: cache2: length: 0, used: 0, occupation: -nan
 281 STATS: cache4: length: 213, used: 56, occupation: 0.262911
 282 Diff: ok
 283 -------------------------------------------
 284 Query: B10 : /site/open_auctions/open_auction[(not(bidder/following::bidder) or not(bidder/preceding::bidder)) and (bidder/following::bidder and bidder/preceding::bidder)]/interval
 285 STATS: parsing xml document: 183.919191ms
 286 STATS: parsing XPath query: 0.127792ms
 287 STATS: compiling XPath query: 0.363827ms
 288 STATS: Query: /child::site/child::open_auctions/child::open_auction[ (not(child::bidder/ancestor-or-self::node()/following-sibling::node()/descendant-or-self::bidder) or not(child::bidder/ancestor-or-self::node()/preceding-sibling::node()/descendant-or-self::bidder)) and child::bidder/ancestor-or-self::node()/following-sibling::node()/descendant-or-self::bidder and child::bidder/ancestor-or-self::node()/preceding-sibling::node()/descendant-or-self::bidder ]/child::interval
 289 STATS: Automaton:
 290 STATS: 1 nodes over 254301 were skipped in iteration 0 (0.00 %), redo is: true
 291 STATS: 251143 nodes over 254301 were skipped in iteration 1 (98.76 %), redo is: true
 292 STATS: 254301 nodes over 254301 were skipped in iteration 2 (100.00 %), redo is: false
 293 STATS: evaluating query: 221.321106ms
 294 STATS: serializing results: 1.529217ms
 295 STATS: 254301 nodes over 254301 were skipped in iteration 3 (100.00 %), redo is: false
 296 STATS: 3 iterations
 297 STATS: automaton 0, cache2: 0 entries, cache6: 153 entries
 298 STATS: cache2: length: 0, used: 0, occupation: -nan
 299 STATS: cache4: length: 208, used: 55, occupation: 0.264423
 300 Diff: ok
 301 -------------------------------------------
 302 Query: B11 : //open_auction/bidder/../bidder/../bidder/../interval
 303 STATS: parsing xml document: 190.995932ms
 304 STATS: parsing XPath query: 0.072956ms
 305 STATS: compiling XPath query: 0.244856ms
 306 STATS: Query: /descendant-or-self::node()/child::open_auction/child::bidder/parent::node()/child::bidder/parent::node()/child::bidder/parent::node()/child::interval
 307 STATS: Automaton:
 308 STATS: 0 nodes over 254301 were skipped in iteration 0 (0.00 %), redo is: true
 309 STATS: 236211 nodes over 254301 were skipped in iteration 1 (92.89 %), redo is: true
 310 STATS: 236211 nodes over 254301 were skipped in iteration 2 (92.89 %), redo is: true
 311 STATS: 254301 nodes over 254301 were skipped in iteration 3 (100.00 %), redo is: false
 312 STATS: evaluating query: 225.605011ms
 313 STATS: serializing results: 6.007910ms
 314 STATS: 254301 nodes over 254301 were skipped in iteration 4 (100.00 %), redo is: false
 315 STATS: 4 iterations
 316 STATS: automaton 0, cache2: 0 entries, cache6: 144 entries
 317 STATS: cache2: length: 0, used: 0, occupation: -nan
 318 STATS: cache4: length: 209, used: 65, occupation: 0.311005
 319 Diff: ok
 320 -------------------------------------------
 321 Query: B12 : //item/@id/../@id/../@id/../@id/../name
 322 STATS: parsing xml document: 194.081068ms
 323 STATS: parsing XPath query: 0.083923ms
 324 STATS: compiling XPath query: 0.293016ms
 325 STATS: Query: /descendant-or-self::node()/child::item/attribute::@id/parent::node()/attribute::@id/parent::node()/attribute::@id/parent::node()/attribute::@id/parent::node()/child::name
 326 STATS: Automaton:
 327 STATS: 0 nodes over 254301 were skipped in iteration 0 (0.00 %), redo is: true
 328 STATS: 188718 nodes over 254301 were skipped in iteration 1 (74.21 %), redo is: true
 329 STATS: 188718 nodes over 254301 were skipped in iteration 2 (74.21 %), redo is: true
 330 STATS: 188718 nodes over 254301 were skipped in iteration 3 (74.21 %), redo is: true
 331 STATS: 254301 nodes over 254301 were skipped in iteration 4 (100.00 %), redo is: false
 332 STATS: evaluating query: 266.115189ms
 333 STATS: serializing results: 5.604982ms
 334 STATS: 254301 nodes over 254301 were skipped in iteration 5 (100.00 %), redo is: false
 335 STATS: 5 iterations
 336 STATS: automaton 0, cache2: 0 entries, cache6: 416 entries
 337 STATS: cache2: length: 0, used: 0, occupation: -nan
 338 STATS: cache4: length: 524, used: 108, occupation: 0.206107
 339 Diff: ok
 340 -------------------------------------------
 341 Query: B13 : //keyword/ancestor::parlist/descendant::keyword/ancestor::parlist/descendant::keyword/ancestor::parlist/descendant::keyword
 342 STATS: parsing xml document: 183.907986ms
 343 STATS: parsing XPath query: 0.083923ms
 344 STATS: compiling XPath query: 0.251055ms
 345 STATS: Query: /descendant-or-self::node()/child::keyword/ancestor::parlist/descendant::keyword/ancestor::parlist/descendant::keyword/ancestor::parlist/descendant::keyword
 346 STATS: Automaton:
 347 STATS: 203073 nodes over 254301 were skipped in iteration 0 (79.86 %), redo is: true
 348 STATS: 208107 nodes over 254301 were skipped in iteration 1 (81.83 %), redo is: true
 349 STATS: 208107 nodes over 254301 were skipped in iteration 2 (81.83 %), redo is: true
 350 STATS: 254301 nodes over 254301 were skipped in iteration 3 (100.00 %), redo is: false
 351 STATS: evaluating query: 197.850943ms
 352 STATS: serializing results: 14.370203ms
 353 STATS: 254301 nodes over 254301 were skipped in iteration 4 (100.00 %), redo is: false
 354 STATS: 4 iterations
 355 STATS: automaton 0, cache2: 0 entries, cache6: 981 entries
 356 STATS: cache2: length: 0, used: 0, occupation: -nan
 357 STATS: cache4: length: 1198, used: 217, occupation: 0.181135
 358 Diff: ok
 359 -------------------------------------------