Bug#750785: Slowness with context and xetex
Hi Behdad, I just returned and saw with great pleasure a new release which fixes the problem. I confirm that xetex now runs like hell again ;-) Thanks for the great support and help, I will surely disturb you again in case of problem. Thanks also to Hilmar for doing the last rounds of testing and debugging! All the best Norbert PREINING, Norbert http://www.preining.info JAIST, Japan TeX Live Debian Developer GPG: 0x860CDC13 fp: F7D8 A928 26E3 16A1 9FA0 ACF0 6CAC A448 860C DC13 -- To UNSUBSCRIBE, email to debian-bugs-dist-requ...@lists.debian.org with a subject of unsubscribe. Trouble? Contact listmas...@lists.debian.org
Bug#750785: Slowness with context and xetex
Thanks Norbert. Was a pleasure working with you. Cheers, behdad On 14-08-19 10:53 AM, Norbert Preining wrote: Hi Behdad, I just returned and saw with great pleasure a new release which fixes the problem. I confirm that xetex now runs like hell again ;-) Thanks for the great support and help, I will surely disturb you again in case of problem. Thanks also to Hilmar for doing the last rounds of testing and debugging! All the best Norbert PREINING, Norbert http://www.preining.info JAIST, Japan TeX Live Debian Developer GPG: 0x860CDC13 fp: F7D8 A928 26E3 16A1 9FA0 ACF0 6CAC A448 860C DC13 -- behdad http://behdad.org/ -- To UNSUBSCRIBE, email to debian-bugs-dist-requ...@lists.debian.org with a subject of unsubscribe. Trouble? Contact listmas...@lists.debian.org
Bug#750785: Slowness with context and xetex
On 14-08-13 12:14 PM, Hilmar Preusse wrote: On 12.08.14 Behdad Esfahbod (beh...@behdad.org) wrote: Hi Behdad, Attached. I just wanted confirm that then patch solves the problem. The harfbuzz maintainer has uploaded a new package to Debian. Thanks Hilmer. I'll make a release today. -- behdad http://behdad.org/ -- To UNSUBSCRIBE, email to debian-bugs-dist-requ...@lists.debian.org with a subject of unsubscribe. Trouble? Contact listmas...@lists.debian.org
Bug#750785: Slowness with context and xetex
On 12.08.14 Behdad Esfahbod (beh...@behdad.org) wrote: Hi Behdad, Attached. I just wanted confirm that then patch solves the problem. The harfbuzz maintainer has uploaded a new package to Debian. Hilmar -- sigmentation fault signature.asc Description: Digital signature
Bug#750785: Slowness with context and xetex
On 11.08.14 Behdad Esfahbod (beh...@behdad.org) wrote: Hi, Before the return, add something like this: printf(DEBUG props %d features %d default_shaper %d shaper_list %d plan func %p proposal func %p\n, hb_segment_properties_equal (shape_plan-props, proposal-props), hb_shape_plan_user_features_match (shape_plan, proposal), shape_plan-default_shaper_list, proposal-shaper_list == NULL, shape_plan-shaper_func, proposal-shaper_func); I left the code provided by Norbert active and redirected all output to stderr. The log is attached (xetex run was terminated). Please be aware, that the uncompressed file has a size of 280 MB. Hilmar -- sigmentation fault out.log.xz Description: Binary data signature.asc Description: Digital signature
Bug#750785: Slowness with context and xetex
Humm. Ok, it looks suspicious, but also helpful. Let me think about it. On 14-08-12 07:12 AM, Hilmar Preusse wrote: On 11.08.14 Behdad Esfahbod (beh...@behdad.org) wrote: Hi, Before the return, add something like this: printf(DEBUG props %d features %d default_shaper %d shaper_list %d plan func %p proposal func %p\n, hb_segment_properties_equal (shape_plan-props, proposal-props), hb_shape_plan_user_features_match (shape_plan, proposal), shape_plan-default_shaper_list, proposal-shaper_list == NULL, shape_plan-shaper_func, proposal-shaper_func); I left the code provided by Norbert active and redirected all output to stderr. The log is attached (xetex run was terminated). Please be aware, that the uncompressed file has a size of 280 MB. Hilmar -- behdad http://behdad.org/ -- To UNSUBSCRIBE, email to debian-bugs-dist-requ...@lists.debian.org with a subject of unsubscribe. Trouble? Contact listmas...@lists.debian.org
Bug#750785: Slowness with context and xetex
Ok, confirmed as HarfBuzz bug. Reproduced. Working on a fix. On 14-08-12 07:12 AM, Hilmar Preusse wrote: On 11.08.14 Behdad Esfahbod (beh...@behdad.org) wrote: Hi, Before the return, add something like this: printf(DEBUG props %d features %d default_shaper %d shaper_list %d plan func %p proposal func %p\n, hb_segment_properties_equal (shape_plan-props, proposal-props), hb_shape_plan_user_features_match (shape_plan, proposal), shape_plan-default_shaper_list, proposal-shaper_list == NULL, shape_plan-shaper_func, proposal-shaper_func); I left the code provided by Norbert active and redirected all output to stderr. The log is attached (xetex run was terminated). Please be aware, that the uncompressed file has a size of 280 MB. Hilmar -- behdad http://behdad.org/ -- To UNSUBSCRIBE, email to debian-bugs-dist-requ...@lists.debian.org with a subject of unsubscribe. Trouble? Contact listmas...@lists.debian.org
Bug#750785: Slowness with context and xetex
The cache wasn't working if more than one (valid) shapers were passed in. Fixed now: https://github.com/behdad/harfbuzz/commit/8d5eebc0c6ada01128c6ee384340efdbef7ba29d behdad On 14-08-12 07:12 AM, Hilmar Preusse wrote: On 11.08.14 Behdad Esfahbod (beh...@behdad.org) wrote: Hi, Before the return, add something like this: printf(DEBUG props %d features %d default_shaper %d shaper_list %d plan func %p proposal func %p\n, hb_segment_properties_equal (shape_plan-props, proposal-props), hb_shape_plan_user_features_match (shape_plan, proposal), shape_plan-default_shaper_list, proposal-shaper_list == NULL, shape_plan-shaper_func, proposal-shaper_func); I left the code provided by Norbert active and redirected all output to stderr. The log is attached (xetex run was terminated). Please be aware, that the uncompressed file has a size of 280 MB. Hilmar -- behdad http://behdad.org/ -- To UNSUBSCRIBE, email to debian-bugs-dist-requ...@lists.debian.org with a subject of unsubscribe. Trouble? Contact listmas...@lists.debian.org
Bug#750785: Slowness with context and xetex
On 12.08.14 Behdad Esfahbod (beh...@behdad.org) wrote: Hi Behdad, https://github.com/behdad/harfbuzz/commit/8d5eebc0c6ada01128c6ee384340efdbef7ba29d I'm failing to pull a raw unified diff out of github. Could you post it here? Tnanks, Hilmar -- sigmentation fault signature.asc Description: Digital signature
Bug#750785: Slowness with context and xetex
On 12.08.14 Norbert Preining (prein...@logic.at) wrote: Hi Norbert, This is a harfbuzz bug? Should be re-assign that bug? Let us wait. It could also be one of the many gcc 4.9 compiler bugs. Can you try compiling harfbuzz and/or xetex with gcc 4.8 instead and see if that changes anything? Will test the patch from Behdad first. H. -- sigmentation fault signature.asc Description: Digital signature
Bug#750785: Slowness with context and xetex
-BEGIN PGP SIGNED MESSAGE-
Hash: SHA1
Attached.
On 14-08-12 05:31 PM, Hilmar Preusse wrote:
On 12.08.14 Behdad Esfahbod (beh...@behdad.org) wrote:
Hi Behdad,
https://github.com/behdad/harfbuzz/commit/8d5eebc0c6ada01128c6ee384340efdbef7ba29d
I'm failing to pull a raw unified diff out of github. Could you post
it here?
Tnanks, Hilmar
- --
behdad
http://behdad.org/
-BEGIN PGP SIGNATURE-
Version: GnuPG v1.4.11 (GNU/Linux)
iEYEARECAAYFAlPqjK4ACgkQn+4E5dNTERUkowCfV1bDY1KIl1+dhhGq9WPstAnf
piEAoImHbpGBgETHMK7wRUm5/c/QVL03
=M1g2
-END PGP SIGNATURE-
commit 8d5eebc0c6ada01128c6ee384340efdbef7ba29d
Author: Behdad Esfahbod beh...@behdad.org
Date: Tue Aug 12 16:50:22 2014 -0400
[shape-plan] Fix shape-plan caching with more than one requested shaper
Wasn't breaking out of loop, ouch!
http://www.mail-archive.com/debian-bugs-dist@lists.debian.org/msg1246370.html
diff --git a/src/hb-shape-plan.cc b/src/hb-shape-plan.cc
index fa0db6a..23beda1 100644
--- a/src/hb-shape-plan.cc
+++ b/src/hb-shape-plan.cc
@@ -420,17 +420,20 @@ hb_shape_plan_create_cached (hb_face_t *face,
if (shaper_list) {
/* Choose shaper. Adapted from hb_shape_plan_plan(). */
#define HB_SHAPER_PLAN(shaper) \
- HB_STMT_START { \
+ { \
if (hb_##shaper##_shaper_face_data_ensure (face)) \
+ { \
proposal.shaper_func = _hb_##shaper##_shape; \
- } HB_STMT_END
+ break; \
+ } \
+ }
for (const char * const *shaper_item = shaper_list; *shaper_item; shaper_item++)
if (0)
;
#define HB_SHAPER_IMPLEMENT(shaper) \
else if (0 == strcmp (*shaper_item, #shaper)) \
- HB_SHAPER_PLAN (shaper);
+ HB_SHAPER_PLAN (shaper)
#include hb-shaper-list.hh
#undef HB_SHAPER_IMPLEMENT
Bug#750785: Slowness with context and xetex
This looks fine. Try passing NULL for shaperList and see if that changes
anything.
If it doesn't, then something in our shape_plan_cache isn't working. I
have a hard time imagining what though.
On Mon, Aug 11, 2014 at 1:55 AM, Norbert Preining prein...@logic.at wrote:
Hi Behdad,
I have now done the following changes in XeTeXLayoutInterface.cpp
(somewhere aboce the surrounding function, declar curtime and nxttime)
static time_t curtime;
static time_t nxttime;
int
layoutChars(XeTeXLayoutEngine engine, uint16_t chars[], int32_t offset,
int32_t count, int32_t max,
bool rightToLeft)
{
...
curtime = time(NULL);
fprintf(stderr, DEBUG [%d] hbFace=%d, segment_props.script=%d,
segment_props.direction=%d, segment-props.language=%d,
engine-nFeatures=%d, shaperList=%s\n,
curtime, hbFace, segment_props.script,
segment_props.direction, segment_props.language, engine-nFeatures,
engine-ShaperList);
shape_plan = hb_shape_plan_create_cached(hbFace, segment_props,
engine-features, engine-nFeatures, engine-ShaperList);
nxttime = time(NULL);
fprintf(stderr, DEBUG [%d] %d return from
hb_shape_plan_create_cached\n, nxttime, nxttime-curtime);
I don't know if this is enough, but I got loads of lines of course,
and about 300 or more where there is
1
so a second of working time in hb_shape_plan_create_cached.
Concerning the other values:
hbFace: in total 5 different values, 4 at the beginning and then the same
segment_props.script switches between 0 and 1281455214, but most of the
time
it is 128...
segment_props.direction is always 4
segment-props.language=44576992
engine-nFeatures=0
shaperList=A81N (printed as %s)
I have uploaded the full output and the test file:
http://www.preining.info/xelatexslow-debug-output.log (21M)
http://www.preining.info/xelatexslow-debug-output.log.gz (98k)
http://www.preining.info/xelatexslow.tex (174k)
Hope that gives you any hint. Let me know if I can provide any
further data.
Thanks a lot
Norbert
PREINING, Norbert http://www.preining.info
JAIST, Japan TeX Live Debian Developer
GPG: 0x860CDC13 fp: F7D8 A928 26E3 16A1 9FA0 ACF0 6CAC A448 860C DC13
--
behdad
http://behdad.org/
Bug#750785: Slowness with context and xetex
Hi, This looks fine. Try passing NULL for shaperList and see if that changes anything. This is about 100 times faster total runtime on that document, with debug output, real 1.845s. What can I try next? For completeness: Debian/sid, harfbuzz shared lib, amd64. Thanks a lot Norbert PREINING, Norbert http://www.preining.info JAIST, Japan TeX Live Debian Developer GPG: 0x860CDC13 fp: F7D8 A928 26E3 16A1 9FA0 ACF0 6CAC A448 860C DC13
Bug#750785: Slowness with context and xetex
Hi
I think I found the bug:
On Mon, 11 Aug 2014, Norbert Preining wrote:
This is about 100 times faster total runtime on that document, with
debug output, real 1.845s.
I recompiled harfbuzz with some debug statements in the
function, and it turned out that when I do that:
(in src/hb-shape-plan.cc, function hb_shape_plan_create_cached
...
retry:
fprintf(stderr, DEBUG harfbuzz: after retry label\n);
hb_face_t::plan_node_t *cached_plan_nodes = (hb_face_t::plan_node_t *)
hb_atomic_ptr_get (face-shape_plans);
for (hb_face_t::plan_node_t *node = cached_plan_nodes; node; node =
node-next) {
fprintf(stderr, DEBUG harfbuzz node for loop\n);
if (hb_shape_plan_matches (node-shape_plan, proposal)) {
fprintf(stderr, DEBUG harfbuzz return from node loop\n);
return hb_shape_plan_reference (node-shape_plan);
}
}
...
THat the loop is getting longer and longer and longer and longer.
For each iteration it loops one more time!! I only send you
the start of the log output:
.
DEBUG [1407750920] 0 return from hb_shape_plan_create_cached
DEBUG [1407750920] hbFace=47040112, segment_props.script=1281455214,
segment_props.direction=4, segment-props.language=47792128,
engine-nFeatures=0, shaperList=¨1N
DEBUG harfbuzz: after retry label
DEBUG harfbuzz node for loop
DEBUG harfbuzz node for loop
DEBUG harfbuzz: before shape_plan_create
DEBUG harfbuzz: before calloc
DEBUG [1407750920] 0 return from hb_shape_plan_create_cached
DEBUG [1407750920] hbFace=47040112, segment_props.script=1281455214,
segment_props.direction=4, segment-props.language=47792128,
engine-nFeatures=0, shaperList=¨1N
DEBUG harfbuzz: after retry label
DEBUG harfbuzz node for loop
DEBUG harfbuzz node for loop
DEBUG harfbuzz node for loop
DEBUG harfbuzz: before shape_plan_create
DEBUG harfbuzz: before calloc
DEBUG [1407750920] 0 return from hb_shape_plan_create_cached
DEBUG [1407750920] hbFace=47040112, segment_props.script=1281455214,
segment_props.direction=4, segment-props.language=47792128,
engine-nFeatures=0, shaperList=¨1N
DEBUG harfbuzz: after retry label
DEBUG harfbuzz node for loop
DEBUG harfbuzz node for loop
DEBUG harfbuzz node for loop
DEBUG harfbuzz node for loop
DEBUG harfbuzz: before shape_plan_create
DEBUG harfbuzz: before calloc
DEBUG [1407750920] 0 return from hb_shape_plan_create_cached
SO with every char another loop element is added.
Still on the first page, I already had:
[~/foo] grep loop xelatexslow-debug-output.log | wc -l
6249880
...
That explains why it is getting s slow ...
I cannot dig into the code now, but this is for sure not
planned ;-)
Norbert
PREINING, Norbert http://www.preining.info
JAIST, Japan TeX Live Debian Developer
GPG: 0x860CDC13 fp: F7D8 A928 26E3 16A1 9FA0 ACF0 6CAC A448 860C DC13
--
To UNSUBSCRIBE, email to debian-bugs-dist-requ...@lists.debian.org
with a subject of unsubscribe. Trouble? Contact listmas...@lists.debian.org
Bug#750785: Slowness with context and xetex
On 11.08.14 Norbert Preining (prein...@logic.at) wrote: Hi, I think I found the bug: Many thanks for investigation! On Mon, 11 Aug 2014, Norbert Preining wrote: This is about 100 times faster total runtime on that document, with debug output, real 1.845s. I recompiled harfbuzz with some debug statements in the function, and it turned out that when I do that: (in src/hb-shape-plan.cc, function hb_shape_plan_create_cached This is a harfbuzz bug? Should be re-assign that bug? H. -- sigmentation fault signature.asc Description: Digital signature
Bug#750785: Slowness with context and xetex
That certainly isn't working as intended. I tested the cache locally (not in
the context of XeTeX) and it works fine.
Can you dig into hb_shape_plan_matches() and see why it's never matching?
On 14-08-11 06:01 AM, Norbert Preining wrote:
Hi
I think I found the bug:
On Mon, 11 Aug 2014, Norbert Preining wrote:
This is about 100 times faster total runtime on that document, with
debug output, real 1.845s.
I recompiled harfbuzz with some debug statements in the
function, and it turned out that when I do that:
(in src/hb-shape-plan.cc, function hb_shape_plan_create_cached
...
retry:
fprintf(stderr, DEBUG harfbuzz: after retry label\n);
hb_face_t::plan_node_t *cached_plan_nodes = (hb_face_t::plan_node_t *)
hb_atomic_ptr_get (face-shape_plans);
for (hb_face_t::plan_node_t *node = cached_plan_nodes; node; node =
node-next) {
fprintf(stderr, DEBUG harfbuzz node for loop\n);
if (hb_shape_plan_matches (node-shape_plan, proposal)) {
fprintf(stderr, DEBUG harfbuzz return from node loop\n);
return hb_shape_plan_reference (node-shape_plan);
}
}
...
THat the loop is getting longer and longer and longer and longer.
For each iteration it loops one more time!! I only send you
the start of the log output:
.
DEBUG [1407750920] 0 return from hb_shape_plan_create_cached
DEBUG [1407750920] hbFace=47040112, segment_props.script=1281455214,
segment_props.direction=4, segment-props.language=47792128,
engine-nFeatures=0, shaperList=¨1N
DEBUG harfbuzz: after retry label
DEBUG harfbuzz node for loop
DEBUG harfbuzz node for loop
DEBUG harfbuzz: before shape_plan_create
DEBUG harfbuzz: before calloc
DEBUG [1407750920] 0 return from hb_shape_plan_create_cached
DEBUG [1407750920] hbFace=47040112, segment_props.script=1281455214,
segment_props.direction=4, segment-props.language=47792128,
engine-nFeatures=0, shaperList=¨1N
DEBUG harfbuzz: after retry label
DEBUG harfbuzz node for loop
DEBUG harfbuzz node for loop
DEBUG harfbuzz node for loop
DEBUG harfbuzz: before shape_plan_create
DEBUG harfbuzz: before calloc
DEBUG [1407750920] 0 return from hb_shape_plan_create_cached
DEBUG [1407750920] hbFace=47040112, segment_props.script=1281455214,
segment_props.direction=4, segment-props.language=47792128,
engine-nFeatures=0, shaperList=¨1N
DEBUG harfbuzz: after retry label
DEBUG harfbuzz node for loop
DEBUG harfbuzz node for loop
DEBUG harfbuzz node for loop
DEBUG harfbuzz node for loop
DEBUG harfbuzz: before shape_plan_create
DEBUG harfbuzz: before calloc
DEBUG [1407750920] 0 return from hb_shape_plan_create_cached
SO with every char another loop element is added.
Still on the first page, I already had:
[~/foo] grep loop xelatexslow-debug-output.log | wc -l
6249880
...
That explains why it is getting s slow ...
I cannot dig into the code now, but this is for sure not
planned ;-)
Norbert
PREINING, Norbert http://www.preining.info
JAIST, Japan TeX Live Debian Developer
GPG: 0x860CDC13 fp: F7D8 A928 26E3 16A1 9FA0 ACF0 6CAC A448 860C DC13
--
behdad
http://behdad.org/
--
To UNSUBSCRIBE, email to debian-bugs-dist-requ...@lists.debian.org
with a subject of unsubscribe. Trouble? Contact listmas...@lists.debian.org
Bug#750785: Slowness with context and xetex
I'll do, after I am back from holidays ;-)
PREINING, Norbert http://www.preining.info
JAIST, Japan TeX Live Debian Developer
GPG: 0x860CDC13 fp: F7D8 A928 26E3 16A1 9FA0 ACF0 6CAC A448 860C DC13
On 2014/08/12, at 0:23, Behdad Esfahbod beh...@behdad.org wrote:
That certainly isn't working as intended. I tested the cache locally (not in
the context of XeTeX) and it works fine.
Can you dig into hb_shape_plan_matches() and see why it's never matching?
On 14-08-11 06:01 AM, Norbert Preining wrote:
Hi
I think I found the bug:
On Mon, 11 Aug 2014, Norbert Preining wrote:
This is about 100 times faster total runtime on that document, with
debug output, real 1.845s.
I recompiled harfbuzz with some debug statements in the
function, and it turned out that when I do that:
(in src/hb-shape-plan.cc, function hb_shape_plan_create_cached
...
retry:
fprintf(stderr, DEBUG harfbuzz: after retry label\n);
hb_face_t::plan_node_t *cached_plan_nodes = (hb_face_t::plan_node_t *)
hb_atomic_ptr_get (face-shape_plans);
for (hb_face_t::plan_node_t *node = cached_plan_nodes; node; node =
node-next) {
fprintf(stderr, DEBUG harfbuzz node for loop\n);
if (hb_shape_plan_matches (node-shape_plan, proposal)) {
fprintf(stderr, DEBUG harfbuzz return from node loop\n);
return hb_shape_plan_reference (node-shape_plan);
}
}
...
THat the loop is getting longer and longer and longer and longer.
For each iteration it loops one more time!! I only send you
the start of the log output:
.
DEBUG [1407750920] 0 return from hb_shape_plan_create_cached
DEBUG [1407750920] hbFace=47040112, segment_props.script=1281455214,
segment_props.direction=4, segment-props.language=47792128,
engine-nFeatures=0, shaperList=¨1N
DEBUG harfbuzz: after retry label
DEBUG harfbuzz node for loop
DEBUG harfbuzz node for loop
DEBUG harfbuzz: before shape_plan_create
DEBUG harfbuzz: before calloc
DEBUG [1407750920] 0 return from hb_shape_plan_create_cached
DEBUG [1407750920] hbFace=47040112, segment_props.script=1281455214,
segment_props.direction=4, segment-props.language=47792128,
engine-nFeatures=0, shaperList=¨1N
DEBUG harfbuzz: after retry label
DEBUG harfbuzz node for loop
DEBUG harfbuzz node for loop
DEBUG harfbuzz node for loop
DEBUG harfbuzz: before shape_plan_create
DEBUG harfbuzz: before calloc
DEBUG [1407750920] 0 return from hb_shape_plan_create_cached
DEBUG [1407750920] hbFace=47040112, segment_props.script=1281455214,
segment_props.direction=4, segment-props.language=47792128,
engine-nFeatures=0, shaperList=¨1N
DEBUG harfbuzz: after retry label
DEBUG harfbuzz node for loop
DEBUG harfbuzz node for loop
DEBUG harfbuzz node for loop
DEBUG harfbuzz node for loop
DEBUG harfbuzz: before shape_plan_create
DEBUG harfbuzz: before calloc
DEBUG [1407750920] 0 return from hb_shape_plan_create_cached
SO with every char another loop element is added.
Still on the first page, I already had:
[~/foo] grep loop xelatexslow-debug-output.log | wc -l
6249880
...
That explains why it is getting s slow ...
I cannot dig into the code now, but this is for sure not
planned ;-)
Norbert
PREINING, Norbert http://www.preining.info
JAIST, Japan TeX Live Debian Developer
GPG: 0x860CDC13 fp: F7D8 A928 26E3 16A1 9FA0 ACF0 6CAC A448 860C DC13
--
behdad
http://behdad.org/
Bug#750785: Slowness with context and xetex
Cold turkey!
On 14-08-11 04:06 PM, Norbert Preining wrote:
I'll do, after I am back from holidays ;-)
PREINING, Norbert http://www.preining.info
http://www.preining.info/
JAIST, Japan TeX Live Debian Developer
GPG: 0x860CDC13 fp: F7D8 A928 26E3 16A1 9FA0 ACF0 6CAC A448 860C DC13
On 2014/08/12, at 0:23, Behdad Esfahbod beh...@behdad.org
mailto:beh...@behdad.org wrote:
That certainly isn't working as intended. I tested the cache locally (not in
the context of XeTeX) and it works fine.
Can you dig into hb_shape_plan_matches() and see why it's never matching?
On 14-08-11 06:01 AM, Norbert Preining wrote:
Hi
I think I found the bug:
On Mon, 11 Aug 2014, Norbert Preining wrote:
This is about 100 times faster total runtime on that document, with
debug output, real 1.845s.
I recompiled harfbuzz with some debug statements in the
function, and it turned out that when I do that:
(in src/hb-shape-plan.cc http://hb-shape-plan.cc, function
hb_shape_plan_create_cached
...
retry:
fprintf(stderr, DEBUG harfbuzz: after retry label\n);
hb_face_t::plan_node_t *cached_plan_nodes = (hb_face_t::plan_node_t *)
hb_atomic_ptr_get (face-shape_plans);
for (hb_face_t::plan_node_t *node = cached_plan_nodes; node; node =
node-next) {
fprintf(stderr, DEBUG harfbuzz node for loop\n);
if (hb_shape_plan_matches (node-shape_plan, proposal)) {
fprintf(stderr, DEBUG harfbuzz return from node loop\n);
return hb_shape_plan_reference (node-shape_plan);
}
}
...
THat the loop is getting longer and longer and longer and longer.
For each iteration it loops one more time!! I only send you
the start of the log output:
.
DEBUG [1407750920] 0 return from hb_shape_plan_create_cached
DEBUG [1407750920] hbFace=47040112, segment_props.script=1281455214,
segment_props.direction=4, segment-props.language=47792128,
engine-nFeatures=0, shaperList=¨1N
DEBUG harfbuzz: after retry label
DEBUG harfbuzz node for loop
DEBUG harfbuzz node for loop
DEBUG harfbuzz: before shape_plan_create
DEBUG harfbuzz: before calloc
DEBUG [1407750920] 0 return from hb_shape_plan_create_cached
DEBUG [1407750920] hbFace=47040112, segment_props.script=1281455214,
segment_props.direction=4, segment-props.language=47792128,
engine-nFeatures=0, shaperList=¨1N
DEBUG harfbuzz: after retry label
DEBUG harfbuzz node for loop
DEBUG harfbuzz node for loop
DEBUG harfbuzz node for loop
DEBUG harfbuzz: before shape_plan_create
DEBUG harfbuzz: before calloc
DEBUG [1407750920] 0 return from hb_shape_plan_create_cached
DEBUG [1407750920] hbFace=47040112, segment_props.script=1281455214,
segment_props.direction=4, segment-props.language=47792128,
engine-nFeatures=0, shaperList=¨1N
DEBUG harfbuzz: after retry label
DEBUG harfbuzz node for loop
DEBUG harfbuzz node for loop
DEBUG harfbuzz node for loop
DEBUG harfbuzz node for loop
DEBUG harfbuzz: before shape_plan_create
DEBUG harfbuzz: before calloc
DEBUG [1407750920] 0 return from hb_shape_plan_create_cached
SO with every char another loop element is added.
Still on the first page, I already had:
[~/foo] grep loop xelatexslow-debug-output.log | wc -l
6249880
...
That explains why it is getting s slow ...
I cannot dig into the code now, but this is for sure not
planned ;-)
Norbert
PREINING, Norbert http://www.preining.info
JAIST, Japan TeX Live Debian Developer
GPG: 0x860CDC13 fp: F7D8 A928 26E3 16A1 9FA0 ACF0 6CAC A448 860C DC13
--
behdad
http://behdad.org/
--
behdad
http://behdad.org/
--
To UNSUBSCRIBE, email to debian-bugs-dist-requ...@lists.debian.org
with a subject of unsubscribe. Trouble? Contact listmas...@lists.debian.org
Bug#750785: Slowness with context and xetex
On 11.08.14 Behdad Esfahbod (beh...@behdad.org) wrote:
Hi Behdad,
That certainly isn't working as intended. I tested the cache locally (not in
the context of XeTeX) and it works fine.
At least I can reproduce the growing loops Norbert has seen, after
applying the debug patch.
Can you dig into hb_shape_plan_matches() and see why it's never matching?
The function is:
static hb_bool_t
hb_shape_plan_matches (const hb_shape_plan_t *shape_plan,
const hb_shape_plan_proposal_t *proposal)
{
return hb_segment_properties_equal (shape_plan-props, proposal-props)
hb_shape_plan_user_features_match (shape_plan, proposal)
((shape_plan-default_shaper_list proposal-shaper_list == NULL) ||
(shape_plan-shaper_func == proposal-shaper_func));
}
Could you send me instructions where to put the printf DEBUG
statements? Maybe I can help.
Hilmar
--
sigmentation fault
signature.asc
Description: Digital signature
Bug#750785: Slowness with context and xetex
Thanks Hilmar. See below:
On Mon, Aug 11, 2014 at 5:40 PM, Hilmar Preusse hill...@web.de wrote:
static hb_bool_t
hb_shape_plan_matches (const hb_shape_plan_t *shape_plan,
const hb_shape_plan_proposal_t *proposal)
{
return hb_segment_properties_equal (shape_plan-props,
proposal-props)
hb_shape_plan_user_features_match (shape_plan, proposal)
((shape_plan-default_shaper_list proposal-shaper_list ==
NULL) ||
(shape_plan-shaper_func == proposal-shaper_func));
}
Before the return, add something like this:
printf(DEBUG props %d features %d default_shaper %d shaper_list %d plan
func %p proposal func %p\n,
hb_segment_properties_equal (shape_plan-props, proposal-props),
hb_shape_plan_user_features_match (shape_plan, proposal),
shape_plan-default_shaper_list, proposal-shaper_list == NULL,
shape_plan-shaper_func, proposal-shaper_func);
Bug#750785: Slowness with context and xetex
Hi Hilmar, This is a harfbuzz bug? Should be re-assign that bug? Let us wait. It could also be one of the many gcc 4.9 compiler bugs. Can you try compiling harfbuzz and/or xetex with gcc 4.8 instead and see if that changes anything? Anyway, when I'm back from Hokkaido I can investigate further. Thanks for your action on this front! Norbert PREINING, Norbert http://www.preining.info JAIST, Japan TeX Live Debian Developer GPG: 0x860CDC13 fp: F7D8 A928 26E3 16A1 9FA0 ACF0 6CAC A448 860C DC13
Bug#750785: Slowness with context and xetex
On 14-08-09 11:47 AM, Khaled Hosny wrote: On Tue, Aug 05, 2014 at 03:04:03PM +0900, Norbert Preining wrote: Hi Khaled, concerning the slowness in xelatex and context/xetex, I found now which call is so delaying. I interspersed lots of printf and found that most time the xelatex process is stucked in the following line from XeTeXLayoutInterface.cpp: shape_plan = hb_shape_plan_create_cached(hbFace, segment_props, engine-features, engine-nFeatures, engine-ShaperList); Does this tell you *anything*? In Debian we are running with harfbuzz 0.9.33 at the moment, and I also checked the sources, there is only one completely unrelated patch that Debian adds. The whole output is mostly stucked in function layoutChars, where the above call happens. Do you have any idea where the slowness could come from? It seems - only from reading the name of the function - that maybe something is not proberly cached? I don't really know, may be Behdad have some suggestions. Not without more context (haha). Print out the parameters being passed in to that function and we'll definitely see why the cache isn't working. Also a simple test document is appreciated. I'm cloning XeTeX now. Will see how a build goes... -- behdad http://behdad.org/ -- To UNSUBSCRIBE, email to debian-bugs-dist-requ...@lists.debian.org with a subject of unsubscribe. Trouble? Contact listmas...@lists.debian.org
Bug#750785: Slowness with context and xetex
Hi Behdad,
thanks for your answer, and looking into it.
On Sun, 10 Aug 2014, Behdad Esfahbod wrote:
Not without more context (haha).
I can give more context, easily, but I need some explanation
on *how* to print out information concerning
hbFace
segment_props
engine-features
(the other two are ints and string, so easy).
Print out the parameters being passed in to that function and we'll definitely
see why the cache isn't working.
I will try, I am now digging throught he headers of harfbuzz to see
how to print such beasts.
Also a simple test document is appreciated. I'm cloning XeTeX now. Will see
how a build goes...
Mind the following:
* it does *NOT* happen when xetex is compiled with a static harfbuzz lib
* I only could check, but it happens when compiling xetex with
Debian sid and testing's harfbuzz library as shared lib.
THe test document is trivial:
\documentclass{article}
\usepackage{fontspec}
\begin{document}
lots of lorem ipsum in many paragraphs
\end{document}
So there needs to be long long text.
All the best
Norbert
PREINING, Norbert http://www.preining.info
JAIST, Japan TeX Live Debian Developer
GPG: 0x860CDC13 fp: F7D8 A928 26E3 16A1 9FA0 ACF0 6CAC A448 860C DC13
--
To UNSUBSCRIBE, email to debian-bugs-dist-requ...@lists.debian.org
with a subject of unsubscribe. Trouble? Contact listmas...@lists.debian.org
Bug#750785: Slowness with context and xetex
On Sun, Aug 10, 2014 at 11:17 PM, Norbert Preining prein...@logic.at
wrote:
Hi Behdad,
thanks for your answer, and looking into it.
On Sun, 10 Aug 2014, Behdad Esfahbod wrote:
Not without more context (haha).
I can give more context, easily, but I need some explanation
on *how* to print out information concerning
hbFace
Just print the pointer. We expect one instance per font file. If you see
them change all the time, bug somewhere else.
segment_props
It's a public struct of script (an enum), direction (an enum), and language
(a pointer). All of those have _to_string() functions, but again, just
print as integers.
engine-features
Normally we expect engine-nFeatures to be zero. Even if it's not, the
feature struct is simple and open, and has a to_string() function too.
It's an array of length engine-nFeatures.
(the other two are ints and string, so easy).
Last one is not an string, it's a NULL-terminated array of strings.
Print out the parameters being passed in to that function and we'll
definitely
see why the cache isn't working.
I will try, I am now digging throught he headers of harfbuzz to see
how to print such beasts.
Also a simple test document is appreciated. I'm cloning XeTeX now.
Will see
how a build goes...
Mind the following:
* it does *NOT* happen when xetex is compiled with a static harfbuzz lib
* I only could check, but it happens when compiling xetex with
Debian sid and testing's harfbuzz library as shared lib.
Ok, best that you get that printout first then.
behdad
THe test document is trivial:
\documentclass{article}
\usepackage{fontspec}
\begin{document}
lots of lorem ipsum in many paragraphs
\end{document}
So there needs to be long long text.
All the best
Norbert
PREINING, Norbert http://www.preining.info
JAIST, Japan TeX Live Debian Developer
GPG: 0x860CDC13 fp: F7D8 A928 26E3 16A1 9FA0 ACF0 6CAC A448 860C DC13
--
behdad
http://behdad.org/
Bug#750785: Slowness with context and xetex
Hi thanks Ok, best that you get that printout first then. I will try as soon as I can, but I am leaving for long overdue holiday of one week tomorrow - without my laptop!!! ;-) :-D All the best Norbert PREINING, Norbert http://www.preining.info JAIST, Japan TeX Live Debian Developer GPG: 0x860CDC13 fp: F7D8 A928 26E3 16A1 9FA0 ACF0 6CAC A448 860C DC13 -- To UNSUBSCRIBE, email to debian-bugs-dist-requ...@lists.debian.org with a subject of unsubscribe. Trouble? Contact listmas...@lists.debian.org
Bug#750785: Slowness with context and xetex
Hi Behdad,
I have now done the following changes in XeTeXLayoutInterface.cpp
(somewhere aboce the surrounding function, declar curtime and nxttime)
static time_t curtime;
static time_t nxttime;
int
layoutChars(XeTeXLayoutEngine engine, uint16_t chars[], int32_t offset, int32_t
count, int32_t max,
bool rightToLeft)
{
...
curtime = time(NULL);
fprintf(stderr, DEBUG [%d] hbFace=%d, segment_props.script=%d,
segment_props.direction=%d, segment-props.language=%d, engine-nFeatures=%d,
shaperList=%s\n,
curtime, hbFace, segment_props.script,
segment_props.direction, segment_props.language, engine-nFeatures,
engine-ShaperList);
shape_plan = hb_shape_plan_create_cached(hbFace, segment_props,
engine-features, engine-nFeatures, engine-ShaperList);
nxttime = time(NULL);
fprintf(stderr, DEBUG [%d] %d return from hb_shape_plan_create_cached\n,
nxttime, nxttime-curtime);
I don't know if this is enough, but I got loads of lines of course,
and about 300 or more where there is
1
so a second of working time in hb_shape_plan_create_cached.
Concerning the other values:
hbFace: in total 5 different values, 4 at the beginning and then the same
segment_props.script switches between 0 and 1281455214, but most of the time
it is 128...
segment_props.direction is always 4
segment-props.language=44576992
engine-nFeatures=0
shaperList=A81N (printed as %s)
I have uploaded the full output and the test file:
http://www.preining.info/xelatexslow-debug-output.log (21M)
http://www.preining.info/xelatexslow-debug-output.log.gz (98k)
http://www.preining.info/xelatexslow.tex (174k)
Hope that gives you any hint. Let me know if I can provide any
further data.
Thanks a lot
Norbert
PREINING, Norbert http://www.preining.info
JAIST, Japan TeX Live Debian Developer
GPG: 0x860CDC13 fp: F7D8 A928 26E3 16A1 9FA0 ACF0 6CAC A448 860C DC13
--
To UNSUBSCRIBE, email to debian-bugs-dist-requ...@lists.debian.org
with a subject of unsubscribe. Trouble? Contact listmas...@lists.debian.org
Bug#750785: Slowness with context and xetex
On Tue, Aug 05, 2014 at 03:04:03PM +0900, Norbert Preining wrote: Hi Khaled, concerning the slowness in xelatex and context/xetex, I found now which call is so delaying. I interspersed lots of printf and found that most time the xelatex process is stucked in the following line from XeTeXLayoutInterface.cpp: shape_plan = hb_shape_plan_create_cached(hbFace, segment_props, engine-features, engine-nFeatures, engine-ShaperList); Does this tell you *anything*? In Debian we are running with harfbuzz 0.9.33 at the moment, and I also checked the sources, there is only one completely unrelated patch that Debian adds. The whole output is mostly stucked in function layoutChars, where the above call happens. Do you have any idea where the slowness could come from? It seems - only from reading the name of the function - that maybe something is not proberly cached? I don't really know, may be Behdad have some suggestions. Regards, Khaled -- To UNSUBSCRIBE, email to debian-bugs-dist-requ...@lists.debian.org with a subject of unsubscribe. Trouble? Contact listmas...@lists.debian.org
Bug#750785: Slowness with context and xetex
Hi Khaled, concerning the slowness in xelatex and context/xetex, I found now which call is so delaying. I interspersed lots of printf and found that most time the xelatex process is stucked in the following line from XeTeXLayoutInterface.cpp: shape_plan = hb_shape_plan_create_cached(hbFace, segment_props, engine-features, engine-nFeatures, engine-ShaperList); Does this tell you *anything*? In Debian we are running with harfbuzz 0.9.33 at the moment, and I also checked the sources, there is only one completely unrelated patch that Debian adds. The whole output is mostly stucked in function layoutChars, where the above call happens. Do you have any idea where the slowness could come from? It seems - only from reading the name of the function - that maybe something is not proberly cached? On Wed, 02 Jul 2014, Khaled Hosny wrote: I don't really know, my Ubuntu install only have 2013 packages so I can not do much testing myself, but I'd really be surprised if such slowness was related to HarfBuzz (unless something really wrong is going on). My first guess would be FontConfig, if XeTeX is asked for a font that it can not find it might cause FontConfig regenerate its font database which can be slow, but then again this should happen once for the whole document which is not the case here. All the best Norbert PREINING, Norbert http://www.preining.info JAIST, Japan TeX Live Debian Developer GPG: 0x860CDC13 fp: F7D8 A928 26E3 16A1 9FA0 ACF0 6CAC A448 860C DC13 -- To UNSUBSCRIBE, email to debian-bugs-dist-requ...@lists.debian.org with a subject of unsubscribe. Trouble? Contact listmas...@lists.debian.org
Bug#750785: Slowness with context and xetex
On Mon, Jun 09, 2014 at 08:59:01PM +0900, Norbert Preining wrote:
Hi Khaled,
(please keep Debian bug in Cc)
I already have asked Taco and Hans, but it seems that the same problem
occurs also with xelatex, so I thought I ask you for ideas.
We got a report here at Debian that context when run over xetex
is extremely slow, which I can confirm. THe same happens with
xelatex when loading fontspec.
The test document is a simple
\starttext
lots of lorem ipsum in many paragraphs
\stoptext
or
\documentclass{article}
\usepackage{fontspec}
\begin{document}
lots of lorem ipsum in many paragraphs
\end{document}
and if I run this through texexec --xtx or xelatex,
the page generation slows down, it seems there is a
increasing delay in page generation.
It is interesting that when I drop the original TeX Live (not Debian)
xetex into our /usr/bin, then it is getting fast again.
The difference between TL original and Debian is that we use
shared libraries. For pure text processing the fault should be
in harfbuzz, right? We are having 0.9.28.
Do you have any ideas how to track such a bug? Do you have
any guess where to start?
I don't really know, my Ubuntu install only have 2013 packages so I can
not do much testing myself, but I'd really be surprised if such slowness
was related to HarfBuzz (unless something really wrong is going on). My
first guess would be FontConfig, if XeTeX is asked for a font that it
can not find it might cause FontConfig regenerate its font database
which can be slow, but then again this should happen once for the whole
document which is not the case here.
Regards,
Khaled
--
To UNSUBSCRIBE, email to debian-bugs-dist-requ...@lists.debian.org
with a subject of unsubscribe. Trouble? Contact listmas...@lists.debian.org
Bug#750785: Slowness with context and xetex
Hi Khaled,
(please keep Debian bug in Cc)
I already have asked Taco and Hans, but it seems that the same problem
occurs also with xelatex, so I thought I ask you for ideas.
We got a report here at Debian that context when run over xetex
is extremely slow, which I can confirm. THe same happens with
xelatex when loading fontspec.
The test document is a simple
\starttext
lots of lorem ipsum in many paragraphs
\stoptext
or
\documentclass{article}
\usepackage{fontspec}
\begin{document}
lots of lorem ipsum in many paragraphs
\end{document}
and if I run this through texexec --xtx or xelatex,
the page generation slows down, it seems there is a
increasing delay in page generation.
It is interesting that when I drop the original TeX Live (not Debian)
xetex into our /usr/bin, then it is getting fast again.
The difference between TL original and Debian is that we use
shared libraries. For pure text processing the fault should be
in harfbuzz, right? We are having 0.9.28.
Do you have any ideas how to track such a bug? Do you have
any guess where to start?
Norbert
PREINING, Norbert http://www.preining.info
JAIST, Japan TeX Live Debian Developer
GPG: 0x860CDC13 fp: F7D8 A928 26E3 16A1 9FA0 ACF0 6CAC A448 860C DC13
--
To UNSUBSCRIBE, email to debian-bugs-dist-requ...@lists.debian.org
with a subject of unsubscribe. Trouble? Contact listmas...@lists.debian.org
Bug#750785: Slowness with context and xetex
One more thing - I build the Debian package with
-pg
for profiling, but xetex runs did not produce a gmon.out, so
there is something strange...
On Mon, 09 Jun 2014, Norbert Preining wrote:
Hi Khaled,
(please keep Debian bug in Cc)
I already have asked Taco and Hans, but it seems that the same problem
occurs also with xelatex, so I thought I ask you for ideas.
We got a report here at Debian that context when run over xetex
is extremely slow, which I can confirm. THe same happens with
xelatex when loading fontspec.
The test document is a simple
\starttext
lots of lorem ipsum in many paragraphs
\stoptext
or
\documentclass{article}
\usepackage{fontspec}
\begin{document}
lots of lorem ipsum in many paragraphs
\end{document}
and if I run this through texexec --xtx or xelatex,
the page generation slows down, it seems there is a
increasing delay in page generation.
It is interesting that when I drop the original TeX Live (not Debian)
xetex into our /usr/bin, then it is getting fast again.
The difference between TL original and Debian is that we use
shared libraries. For pure text processing the fault should be
in harfbuzz, right? We are having 0.9.28.
Do you have any ideas how to track such a bug? Do you have
any guess where to start?
Norbert
Norbert
PREINING, Norbert http://www.preining.info
JAIST, Japan TeX Live Debian Developer
GPG: 0x860CDC13 fp: F7D8 A928 26E3 16A1 9FA0 ACF0 6CAC A448 860C DC13
--
To UNSUBSCRIBE, email to debian-bugs-dist-requ...@lists.debian.org
with a subject of unsubscribe. Trouble? Contact listmas...@lists.debian.org
Bug#750785: Slowness with context and xetex
Hi Hans, hi Taco,
(please keep the Debian bug report in Cc)
We got a report here at Debian that context when run over xetex
is extremely slow, which I can confirm.
It is interesting that when I drop the original TeX Live (not Debian)
xetex into our /usr/bin, then it is getting fast again.
On the other hand, I don't see any slow down when running
xelatex on a similar document. The test document is a simple
\starttext
lots of lorem ipsum in paragraphs
\stoptext
If I change this to a simple latex document {article} it is also
very fast.
So that points at something that context is telling xetex to do/load
that exhibits a bug, but I have *NO* idea where the bug might
come from.
The difference between TL original and Debian is that we use
shared libraries. For pure text processing the fault should be
in harfbuzz, right? We are having 0.9.28.
Do you have any other ideas how to track such a bug? Do you have
any guess what could it be that context tells xetex?
Thanks a lot
Norbert
PREINING, Norbert http://www.preining.info
JAIST, Japan TeX Live Debian Developer
GPG: 0x860CDC13 fp: F7D8 A928 26E3 16A1 9FA0 ACF0 6CAC A448 860C DC13
--
To UNSUBSCRIBE, email to debian-bugs-dist-requ...@lists.debian.org
with a subject of unsubscribe. Trouble? Contact listmas...@lists.debian.org
Bug#750785: Slowness with context and xetex
On 6/8/2014 9:26 AM, Norbert Preining wrote:
Hi Hans, hi Taco,
(please keep the Debian bug report in Cc)
We got a report here at Debian that context when run over xetex
is extremely slow, which I can confirm.
It is interesting that when I drop the original TeX Live (not Debian)
xetex into our /usr/bin, then it is getting fast again.
On the other hand, I don't see any slow down when running
xelatex on a similar document. The test document is a simple
\starttext
lots of lorem ipsum in paragraphs
\stoptext
If I change this to a simple latex document {article} it is also
very fast.
So that points at something that context is telling xetex to do/load
that exhibits a bug, but I have *NO* idea where the bug might
come from.
Can you see if (in the background) the xetex font database gets
regenerated? I remember that long ago on windows we had a problem with
xetex, where it could not determine that it had already generated the
database. This can happen when a font is asked for 'by name' which isn't
on the system so that some kind of 'not found, let's regenerate the
database' action happens (which is out of context control).
The difference between TL original and Debian is that we use
shared libraries. For pure text processing the fault should be
in harfbuzz, right? We are having 0.9.28.
Do you have any other ideas how to track such a bug? Do you have
any guess what could it be that context tells xetex?
Thanks a lot
Norbert
PREINING, Norbert http://www.preining.info
JAIST, Japan TeX Live Debian Developer
GPG: 0x860CDC13 fp: F7D8 A928 26E3 16A1 9FA0 ACF0 6CAC A448 860C DC13
--
-
Hans Hagen | PRAGMA ADE
Ridderstraat 27 | 8061 GH Hasselt | The Netherlands
tel: 038 477 53 69 | voip: 087 875 68 74 | www.pragma-ade.com
| www.pragma-pod.nl
-
--
To UNSUBSCRIBE, email to debian-bugs-dist-requ...@lists.debian.org
with a subject of unsubscribe. Trouble? Contact listmas...@lists.debian.org
Bug#750785: Slowness with context and xetex
Hi Hans, thanks for your ideas. Can you see if (in the background) the xetex font database gets regenerated? I remember that long ago on windows we had a problem I didn't see anything running in the background. I also doubt that this is the reason, because xetex on linux will not call fc-cache, right? Looking at the run time it seems that the time for each page is getting longer and longer. I got a similar bug report now for LaTeX - which I couldn't reproduce by now. I guess I have to write to Khaled. Norbert PREINING, Norbert http://www.preining.info JAIST, Japan TeX Live Debian Developer GPG: 0x860CDC13 fp: F7D8 A928 26E3 16A1 9FA0 ACF0 6CAC A448 860C DC13 -- To UNSUBSCRIBE, email to debian-bugs-dist-requ...@lists.debian.org with a subject of unsubscribe. Trouble? Contact listmas...@lists.debian.org
