tests/xmark_tiny.xml.summary

   1 Query: A1 : /site/closed_auctions/closed_auction/annotation/description/text/keyword
   2 STATS: parsing xml document: 1.941919ms
   3 STATS: parsing XPath query: 0.118971ms
   4 STATS: compiling XPath query: 0.624895ms
   5 STATS: Query: /child::site/child::closed_auctions/child::closed_auction/child::annotation/child::description/child::text/child::keyword
   6 STATS: Automaton:
   7 STATS: 1155 nodes over 1155 were skipped in iteration 0 (100.00 %), redo is: false
   8 STATS: evaluating query: 13.736010ms
   9 STATS: serializing results: 1.666784ms
  10 STATS: 1155 nodes over 1155 were skipped in iteration 1 (100.00 %), redo is: false
  11 STATS: 1 iterations
  12 STATS: automaton 0, cache2: 140 entries, cache6: 2831 entries
  13 STATS: cache2: length: 210, used: 70, occupation: 0.333333
  14 STATS: cache4: length: 3099, used: 268, occupation: 0.086480
  15 Diff: ok
  16 -------------------------------------------
  17 Query: A2 : //closed_auction//keyword
  18 STATS: parsing xml document: 1.976013ms
  19 STATS: parsing XPath query: 0.051975ms
  20 STATS: compiling XPath query: 0.267982ms
  21 STATS: Query: /descendant-or-self::node()/child::closed_auction/descendant-or-self::node()/child::keyword
  22 STATS: Automaton:
  23 STATS: 1155 nodes over 1155 were skipped in iteration 0 (100.00 %), redo is: false
  24 STATS: evaluating query: 7.214785ms
  25 STATS: serializing results: 1.543045ms
  26 STATS: 1155 nodes over 1155 were skipped in iteration 1 (100.00 %), redo is: false
  27 STATS: 1 iterations
  28 STATS: automaton 0, cache2: 140 entries, cache6: 2253 entries
  29 STATS: cache2: length: 210, used: 70, occupation: 0.333333
  30 STATS: cache4: length: 2452, used: 199, occupation: 0.081158
  31 Diff: ok
  32 -------------------------------------------
  33 Query: A3 : /site/closed_auctions/closed_auction//keyword
  34 STATS: parsing xml document: 1.937866ms
  35 STATS: parsing XPath query: 0.067949ms
  36 STATS: compiling XPath query: 0.401974ms
  37 STATS: Query: /child::site/child::closed_auctions/child::closed_auction/descendant-or-self::node()/child::keyword
  38 STATS: Automaton:
  39 STATS: 1155 nodes over 1155 were skipped in iteration 0 (100.00 %), redo is: false
  40 STATS: evaluating query: 8.767843ms
  41 STATS: serializing results: 1.557112ms
  42 STATS: 1155 nodes over 1155 were skipped in iteration 1 (100.00 %), redo is: false
  43 STATS: 1 iterations
  44 STATS: automaton 0, cache2: 140 entries, cache6: 2969 entries
  45 STATS: cache2: length: 210, used: 70, occupation: 0.333333
  46 STATS: cache4: length: 3212, used: 243, occupation: 0.075654
  47 Diff: ok
  48 -------------------------------------------
  49 Query: A4 : /site/closed_auctions/closed_auction[annotation/description/text/keyword]/date
  50 STATS: parsing xml document: 2.266884ms
  51 STATS: parsing XPath query: 0.097036ms
  52 STATS: compiling XPath query: 0.423908ms
  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: 1046 nodes over 1155 were skipped in iteration 0 (90.56 %), redo is: true
  56 STATS: 1155 nodes over 1155 were skipped in iteration 1 (100.00 %), redo is: false
  57 STATS: evaluating query: 13.612032ms
  58 STATS: serializing results: 1.475811ms
  59 STATS: 1155 nodes over 1155 were skipped in iteration 2 (100.00 %), redo is: false
  60 STATS: 2 iterations
  61 STATS: automaton 0, cache2: 0 entries, cache6: 269 entries
  62 STATS: cache2: length: 0, used: 0, occupation: -nan
  63 STATS: cache4: length: 341, used: 72, occupation: 0.211144
  64 Diff: ok
  65 -------------------------------------------
  66 Query: A5 : /site/closed_auctions/closed_auction[descendant::keyword]/date
  67 STATS: parsing xml document: 1.949072ms
  68 STATS: parsing XPath query: 0.077963ms
  69 STATS: compiling XPath query: 0.340939ms
  70 STATS: Query: /child::site/child::closed_auctions/child::closed_auction[ descendant::keyword ]/child::date
  71 STATS: Automaton:
  72 STATS: 1046 nodes over 1155 were skipped in iteration 0 (90.56 %), redo is: true
  73 STATS: 1155 nodes over 1155 were skipped in iteration 1 (100.00 %), redo is: false
  74 STATS: evaluating query: 8.916855ms
  75 STATS: serializing results: 1.583099ms
  76 STATS: 1155 nodes over 1155 were skipped in iteration 2 (100.00 %), redo is: false
  77 STATS: 2 iterations
  78 STATS: automaton 0, cache2: 0 entries, cache6: 201 entries
  79 STATS: cache2: length: 0, used: 0, occupation: -nan
  80 STATS: cache4: length: 274, used: 73, occupation: 0.266423
  81 Diff: ok
  82 -------------------------------------------
  83 Query: A6 : /site/people/person[profile/gender and profile/age]/name
  84 STATS: parsing xml document: 1.895189ms
  85 STATS: parsing XPath query: 0.103951ms
  86 STATS: compiling XPath query: 0.425816ms
  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: 1129 nodes over 1155 were skipped in iteration 0 (97.75 %), redo is: true
  90 STATS: 1155 nodes over 1155 were skipped in iteration 1 (100.00 %), redo is: false
  91 STATS: evaluating query: 10.172129ms
  92 STATS: serializing results: 3.078938ms
  93 STATS: 1155 nodes over 1155 were skipped in iteration 2 (100.00 %), redo is: false
  94 STATS: 2 iterations
  95 STATS: automaton 0, cache2: 0 entries, cache6: 66 entries
  96 STATS: cache2: length: 0, used: 0, occupation: -nan
  97 STATS: cache4: length: 95, used: 29, occupation: 0.305263
  98 Diff: ok
  99 -------------------------------------------
 100 Query: A7 : /site/people/person[phone or homepage]/name
 101 STATS: parsing xml document: 1.924038ms
 102 STATS: parsing XPath query: 0.078917ms
 103 STATS: compiling XPath query: 0.349045ms
 104 STATS: Query: /child::site/child::people/child::person[ child::phone or child::homepage ]/child::name
 105 STATS: Automaton:
 106 STATS: 1129 nodes over 1155 were skipped in iteration 0 (97.75 %), redo is: true
 107 STATS: 1155 nodes over 1155 were skipped in iteration 1 (100.00 %), redo is: false
 108 STATS: evaluating query: 8.696079ms
 109 STATS: serializing results: 1.600027ms
 110 STATS: 1155 nodes over 1155 were skipped in iteration 2 (100.00 %), redo is: false
 111 STATS: 2 iterations
 112 STATS: automaton 0, cache2: 0 entries, cache6: 88 entries
 113 STATS: cache2: length: 0, used: 0, occupation: -nan
 114 STATS: cache4: length: 140, used: 52, occupation: 0.371429
 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: 1.899004ms
 119 STATS: parsing XPath query: 0.114918ms
 120 STATS: compiling XPath query: 0.459909ms
 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: 1129 nodes over 1155 were skipped in iteration 0 (97.75 %), redo is: true
 124 STATS: 1155 nodes over 1155 were skipped in iteration 1 (100.00 %), redo is: false
 125 STATS: evaluating query: 11.929989ms
 126 STATS: serializing results: 1.475811ms
 127 STATS: 1155 nodes over 1155 were skipped in iteration 2 (100.00 %), redo is: false
 128 STATS: 2 iterations
 129 STATS: automaton 0, cache2: 0 entries, cache6: 92 entries
 130 STATS: cache2: length: 0, used: 0, occupation: -nan
 131 STATS: cache4: length: 139, used: 47, occupation: 0.338129
 132 Diff: ok
 133 -------------------------------------------
 134 Query: B1 : /site/regions/*/item[parent::namerica or parent::samerica]/name
 135 STATS: parsing xml document: 2.445936ms
 136 STATS: parsing XPath query: 0.091076ms
 137 STATS: compiling XPath query: 0.488997ms
 138 STATS: Query: /child::site/child::regions/child::*/child::item[ parent::namerica or parent::samerica ]/child::name
 139 STATS: Automaton:
 140 STATS: 1155 nodes over 1155 were skipped in iteration 0 (100.00 %), redo is: false
 141 STATS: evaluating query: 8.671999ms
 142 STATS: serializing results: 1.447201ms
 143 STATS: 1155 nodes over 1155 were skipped in iteration 1 (100.00 %), redo is: false
 144 STATS: 1 iterations
 145 STATS: automaton 0, cache2: 140 entries, cache6: 2553 entries
 146 STATS: cache2: length: 210, used: 70, occupation: 0.333333
 147 STATS: cache4: length: 2784, used: 231, occupation: 0.082974
 148 Diff: ok
 149 -------------------------------------------
 150 Query: B2 : //keyword/ancestor::listitem/text/keyword
 151 STATS: parsing xml document: 1.924992ms
 152 STATS: parsing XPath query: 0.075102ms
 153 STATS: compiling XPath query: 0.345945ms
 154 STATS: Query: /descendant-or-self::node()/child::keyword/ancestor::listitem/child::text/child::keyword
 155 STATS: Automaton:
 156 STATS: 838 nodes over 1155 were skipped in iteration 0 (72.55 %), redo is: true
 157 STATS: 1155 nodes over 1155 were skipped in iteration 1 (100.00 %), redo is: false
 158 STATS: evaluating query: 11.610985ms
 159 STATS: serializing results: 1.956940ms
 160 STATS: 1155 nodes over 1155 were skipped in iteration 2 (100.00 %), redo is: false
 161 STATS: 2 iterations
 162 STATS: automaton 0, cache2: 0 entries, cache6: 1079 entries
 163 STATS: cache2: length: 0, used: 0, occupation: -nan
 164 STATS: cache4: length: 1225, used: 146, occupation: 0.119184
 165 Diff: ok
 166 -------------------------------------------
 167 Query: B3 : /site/open_auctions/open_auction/bidder[following-sibling::bidder]
 168 STATS: parsing xml document: 1.966000ms
 169 STATS: parsing XPath query: 0.071049ms
 170 STATS: compiling XPath query: 0.307083ms
 171 STATS: Query: /child::site/child::open_auctions/child::open_auction/child::bidder[ following-sibling::bidder ]
 172 STATS: Automaton:
 173 STATS: 1155 nodes over 1155 were skipped in iteration 0 (100.00 %), redo is: false
 174 STATS: evaluating query: 7.487059ms
 175 STATS: serializing results: 1.948833ms
 176 STATS: 1155 nodes over 1155 were skipped in iteration 1 (100.00 %), redo is: false
 177 STATS: 1 iterations
 178 STATS: automaton 0, cache2: 140 entries, cache6: 2328 entries
 179 STATS: cache2: length: 210, used: 70, occupation: 0.333333
 180 STATS: cache4: length: 2549, used: 221, occupation: 0.086701
 181 Diff: ok
 182 -------------------------------------------
 183 Query: B4 : /site/open_auctions/open_auction/bidder[preceding-sibling::bidder]
 184 STATS: parsing xml document: 1.992941ms
 185 STATS: parsing XPath query: 0.087023ms
 186 STATS: compiling XPath query: 0.313997ms
 187 STATS: Query: /child::site/child::open_auctions/child::open_auction/child::bidder[ preceding-sibling::bidder ]
 188 STATS: Automaton:
 189 STATS: 1155 nodes over 1155 were skipped in iteration 0 (100.00 %), redo is: false
 190 STATS: evaluating query: 7.298946ms
 191 STATS: serializing results: 2.054930ms
 192 STATS: 1155 nodes over 1155 were skipped in iteration 1 (100.00 %), redo is: false
 193 STATS: 1 iterations
 194 STATS: automaton 0, cache2: 140 entries, cache6: 1951 entries
 195 STATS: cache2: length: 210, used: 70, occupation: 0.333333
 196 STATS: cache4: length: 2138, used: 187, occupation: 0.087465
 197 Diff: ok
 198 -------------------------------------------
 199 Query: B5 : /site/regions/*/item[following::item]/name
 200 STATS: parsing xml document: 1.929998ms
 201 STATS: parsing XPath query: 0.079155ms
 202 STATS: compiling XPath query: 0.583172ms
 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 1155 were skipped in iteration 0 (0.09 %), redo is: true
 206 STATS: 1155 nodes over 1155 were skipped in iteration 1 (100.00 %), redo is: false
 207 STATS: evaluating query: 15.670061ms
 208 STATS: serializing results: 1.724005ms
 209 STATS: 1155 nodes over 1155 were skipped in iteration 2 (100.00 %), redo is: false
 210 STATS: 2 iterations
 211 STATS: automaton 0, cache2: 0 entries, cache6: 1372 entries
 212 STATS: cache2: length: 0, used: 0, occupation: -nan
 213 STATS: cache4: length: 1624, used: 252, occupation: 0.155172
 214 Diff: ok
 215 -------------------------------------------
 216 Query: B6 : /site/regions/*/item[preceding::item]/name
 217 STATS: parsing xml document: 2.002954ms
 218 STATS: parsing XPath query: 0.078917ms
 219 STATS: compiling XPath query: 0.535965ms
 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: 1155 nodes over 1155 were skipped in iteration 0 (100.00 %), redo is: false
 223 STATS: evaluating query: 14.605999ms
 224 STATS: serializing results: 1.614094ms
 225 STATS: 1155 nodes over 1155 were skipped in iteration 1 (100.00 %), redo is: false
 226 STATS: 1 iterations
 227 STATS: automaton 0, cache2: 140 entries, cache6: 3069 entries
 228 STATS: cache2: length: 210, used: 70, occupation: 0.333333
 229 STATS: cache4: length: 3392, used: 323, occupation: 0.095224
 230 Diff: ok
 231 -------------------------------------------
 232 Query: B7 : //person[profile/@income]/name
 233 STATS: parsing xml document: 1.917839ms
 234 STATS: parsing XPath query: 0.077963ms
 235 STATS: compiling XPath query: 0.272036ms
 236 STATS: Query: /descendant-or-self::node()/child::person[ child::profile/attribute::@income ]/child::name
 237 STATS: Automaton:
 238 STATS: 1129 nodes over 1155 were skipped in iteration 0 (97.75 %), redo is: true
 239 STATS: 1155 nodes over 1155 were skipped in iteration 1 (100.00 %), redo is: false
 240 STATS: evaluating query: 3.632784ms
 241 STATS: serializing results: 1.396894ms
 242 STATS: 1155 nodes over 1155 were skipped in iteration 2 (100.00 %), redo is: false
 243 STATS: 2 iterations
 244 STATS: automaton 0, cache2: 0 entries, cache6: 58 entries
 245 STATS: cache2: length: 0, used: 0, occupation: -nan
 246 STATS: cache4: length: 84, used: 26, occupation: 0.309524
 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: 1.998901ms
 251 STATS: parsing XPath query: 0.102043ms
 252 STATS: compiling XPath query: 0.397921ms
 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: 1091 nodes over 1155 were skipped in iteration 0 (94.46 %), redo is: true
 256 STATS: 1155 nodes over 1155 were skipped in iteration 1 (100.00 %), redo is: false
 257 STATS: evaluating query: 10.616779ms
 258 STATS: serializing results: 1.590967ms
 259 STATS: 1155 nodes over 1155 were skipped in iteration 2 (100.00 %), redo is: false
 260 STATS: 2 iterations
 261 STATS: automaton 0, cache2: 0 entries, cache6: 124 entries
 262 STATS: cache2: length: 0, used: 0, occupation: -nan
 263 STATS: cache4: length: 184, used: 60, occupation: 0.326087
 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: 1.937151ms
 268 STATS: parsing XPath query: 0.144005ms
 269 STATS: compiling XPath query: 1.156092ms
 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 1155 were skipped in iteration 0 (0.09 %), redo is: true
 273 STATS: 1155 nodes over 1155 were skipped in iteration 1 (100.00 %), redo is: false
 274 STATS: evaluating query: 18.059015ms
 275 STATS: serializing results: 1.640081ms
 276 STATS: 1155 nodes over 1155 were skipped in iteration 2 (100.00 %), redo is: false
 277 STATS: 2 iterations
 278 STATS: automaton 0, cache2: 0 entries, cache6: 977 entries
 279 STATS: cache2: length: 0, used: 0, occupation: -nan
 280 STATS: cache4: length: 1250, used: 273, occupation: 0.218400
 281 Diff: ok
 282 -------------------------------------------
 283 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
 284 STATS: parsing xml document: 1.865864ms
 285 STATS: parsing XPath query: 0.143051ms
 286 STATS: compiling XPath query: 1.295090ms
 287 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
 288 STATS: Automaton:
 289 STATS: 1 nodes over 1155 were skipped in iteration 0 (0.09 %), redo is: true
 290 STATS: 1155 nodes over 1155 were skipped in iteration 1 (100.00 %), redo is: false
 291 STATS: evaluating query: 27.679920ms
 292 STATS: serializing results: 1.658916ms
 293 STATS: 1155 nodes over 1155 were skipped in iteration 2 (100.00 %), redo is: false
 294 STATS: 2 iterations
 295 STATS: automaton 0, cache2: 0 entries, cache6: 978 entries
 296 STATS: cache2: length: 0, used: 0, occupation: -nan
 297 STATS: cache4: length: 1247, used: 269, occupation: 0.215718
 298 Diff: ok
 299 -------------------------------------------
 300 Query: B11 : //open_auction/bidder/../bidder/../bidder/../interval
 301 STATS: parsing xml document: 1.846075ms
 302 STATS: parsing XPath query: 0.068903ms
 303 STATS: compiling XPath query: 0.643015ms
 304 STATS: Query: /descendant-or-self::node()/child::open_auction/child::bidder/parent::node()/child::bidder/parent::node()/child::bidder/parent::node()/child::interval
 305 STATS: Automaton:
 306 STATS: 0 nodes over 1155 were skipped in iteration 0 (0.00 %), redo is: true
 307 STATS: 1091 nodes over 1155 were skipped in iteration 1 (94.46 %), redo is: true
 308 STATS: 1091 nodes over 1155 were skipped in iteration 2 (94.46 %), redo is: true
 309 STATS: 1155 nodes over 1155 were skipped in iteration 3 (100.00 %), redo is: false
 310 STATS: evaluating query: 18.645048ms
 311 STATS: serializing results: 1.463175ms
 312 STATS: 1155 nodes over 1155 were skipped in iteration 4 (100.00 %), redo is: false
 313 STATS: 4 iterations
 314 STATS: automaton 0, cache2: 0 entries, cache6: 93 entries
 315 STATS: cache2: length: 0, used: 0, occupation: -nan
 316 STATS: cache4: length: 149, used: 56, occupation: 0.375839
 317 Diff: ok
 318 -------------------------------------------
 319 Query: B12 : //item/@id/../@id/../@id/../@id/../name
 320 STATS: parsing xml document: 1.981020ms
 321 STATS: parsing XPath query: 0.072002ms
 322 STATS: compiling XPath query: 0.829935ms
 323 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
 324 STATS: Automaton:
 325 STATS: 0 nodes over 1155 were skipped in iteration 0 (0.00 %), redo is: true
 326 STATS: 891 nodes over 1155 were skipped in iteration 1 (77.14 %), redo is: true
 327 STATS: 891 nodes over 1155 were skipped in iteration 2 (77.14 %), redo is: true
 328 STATS: 891 nodes over 1155 were skipped in iteration 3 (77.14 %), redo is: true
 329 STATS: 1155 nodes over 1155 were skipped in iteration 4 (100.00 %), redo is: false
 330 STATS: evaluating query: 20.490885ms
 331 STATS: serializing results: 1.349926ms
 332 STATS: 1155 nodes over 1155 were skipped in iteration 5 (100.00 %), redo is: false
 333 STATS: 5 iterations
 334 STATS: automaton 0, cache2: 0 entries, cache6: 304 entries
 335 STATS: cache2: length: 0, used: 0, occupation: -nan
 336 STATS: cache4: length: 384, used: 80, occupation: 0.208333
 337 Diff: ok
 338 -------------------------------------------
 339 Query: B13 : //keyword/ancestor::parlist/descendant::keyword/ancestor::parlist/descendant::keyword/ancestor::parlist/descendant::keyword
 340 STATS: parsing xml document: 1.920938ms
 341 STATS: parsing XPath query: 0.090837ms
 342 STATS: compiling XPath query: 0.641108ms
 343 STATS: Query: /descendant-or-self::node()/child::keyword/ancestor::parlist/descendant::keyword/ancestor::parlist/descendant::keyword/ancestor::parlist/descendant::keyword
 344 STATS: Automaton:
 345 STATS: 798 nodes over 1155 were skipped in iteration 0 (69.09 %), redo is: true
 346 STATS: 798 nodes over 1155 were skipped in iteration 1 (69.09 %), redo is: true
 347 STATS: 798 nodes over 1155 were skipped in iteration 2 (69.09 %), redo is: true
 348 STATS: 1155 nodes over 1155 were skipped in iteration 3 (100.00 %), redo is: false
 349 STATS: evaluating query: 24.297953ms
 350 STATS: serializing results: 1.913071ms
 351 STATS: 1155 nodes over 1155 were skipped in iteration 4 (100.00 %), redo is: false
 352 STATS: 4 iterations
 353 STATS: automaton 0, cache2: 0 entries, cache6: 660 entries
 354 STATS: cache2: length: 0, used: 0, occupation: -nan
 355 STATS: cache4: length: 817, used: 157, occupation: 0.192166
 356 Diff: ok
 357 -------------------------------------------