Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Indentation takes forever on lines after AUTOINST (with wildcard and elisp function in template rule) #663

Closed
veripoolbot opened this issue Jul 1, 2013 · 4 comments
Labels

Comments

@veripoolbot
Copy link
Collaborator


Author Name: Brad Dobbie
Original Redmine Issue: 663 from https://www.veripool.org
Original Date: 2013-07-01
Original Assignee: Alex Reed


After a recent upgrade of our site's Verilog-mode version, I notice very poor indentation performance under some circumstances.

  • New: You are using verilog-mode 2013-05-30-ed10b51-vpo
  • Old: You are using verilog-mode 2013-04-24-7ab1e46

I've distilled the problem code to this testcase. I need to use a template rule with a regexp matcher and an elisp function call. To observe the problem, place the cursor after the semicolon of the assign statement and press ENTER.

/*AUTO_LISP(
 defun vm-unused-port ()
  (cond ((string-equal vl-dir "input" )
          (concat "{" vl-width "{1'b0}}"))
         ((string-equal vl-dir "output")
          (concat "unused__" vl-cell-name "__" vl-name vl-bits))))
 */

module foo
  (input a0, a1, a2, b0, b1, b2, c0, c1, c2,
    output y);
    assign y = |{a0, a1, a2, b0, b1, b2, c0, c1, c2};
endmodule

module bar
  (input a0, a1, a2,
    output z);

    /* foo AUTO_TEMPLATE(
     .b.+\|c.+                           (@"(vm-unused-port)"),
     );*/
    foo foo
      (/*AUTOINST*/
       // Outputs
       .y                                (y),
       // Inputs
       .a0                               (a0),
       .a1                               (a1),
       .a2                               (a2),
       .b0                               ({1{1'b0}}),             // Templated
       .b1                               ({1{1'b0}}),             // Templated
       .b2                               ({1{1'b0}}),             // Templated
       .c0                               ({1{1'b0}}),             // Templated
       .c1                               ({1{1'b0}}),             // Templated
       .c2                               ({1{1'b0}}));            // Templated

    // Indentation is screwed up after this point
    assign z = y;

endmodule

I'm suspicious of this recent commit:
0e4bf42

@veripoolbot
Copy link
Collaborator Author


Original Redmine Comment
Author Name: Benjamin Richards
Original Date: 2014-05-20T20:40:18Z


Just wanted to point out that I'm seeing this same issue on Emacs 24.3.1. I haven't any good workarounds other than shuffling code around with some copy-pastes to avoid hitting it, and using C-g to abort indentation when it happens.

My version: You are using verilog-mode 2013-10-09-deae5d2-mod-vpo

@veripoolbot
Copy link
Collaborator Author


Original Redmine Comment
Author Name: Wilson Snyder (@wsnyder)
Original Date: 2014-11-04T18:46:20Z


Another example hang

@veripoolbot
Copy link
Collaborator Author


Original Redmine Comment
Author Name: Alex Reed
Original Date: 2014-11-05T22:46:00Z


Using hangcase.v, I was able to bisect the tree and prove that 0e4bf42 did in fact introduce the decrease in performance.


Next, I ran 'elp' on verilog-mode:

1) M-x elp-instrument-package RET verilog- RET
2) M-g M-g 14 RET ; select line 14 of hangcase.v
3) C-a TAB ; go to front, indent
4) M-x elp-results


This returns the following table (boring stuff truncated):

Function Name                             Call Count  Elapsed Time  Average Time
verilog-backward-token                    91914       103.09858929  0.0011216853
verilog-at-constraint-p                   26241       92.427414207  0.0035222519
verilog-beg-of-statement                  13120       87.251770343  0.0066502873
verilog-indent-line                       1           18.641194136  18.641194136
verilog-do-indent                         1           18.63892861   18.63892861
verilog-beg-of-statement-1                2           18.638600888  9.319300444
verilog-backward-syntactic-ws             196985      11.173193975  5.672...e-05
verilog-skip-backward-comments            236347      10.917110170  4.619...e-05
verilog-syntax-ppss                       420058      8.0804870359  1.923...e-05
verilog-backward-ws&directives            39362       2.8406581719  7.216...e-05
verilog-forward-syntactic-ws              13122       0.8940086040  6.813...e-05
verilog-skip-forward-comment-p            13122       0.8007059890  6.102...e-05
verilog-in-attribute-p                    13122       0.3224949939  2.457...e-05
verilog-re-search-backward                13123       0.0793367000  6.045...e-06

The call-count for verilog-backward-token is pretty high - not the highest, but certainly the longest elapsed time. I'd be more concerned about the average times that are >1 but the call-count is low. Admittedly I have no idea how to actually use elp, so this is mostly speculation at this point.


To find out where verilog-backward-token is being called, I inserted the command ```(message "%s\n%s" (point) (backtrace))


<br>

Here's the change I made (sorry about the wacky indention, sloppy use of if/progn, etc...):

diff --git a/verilog-mode.el b/verilog-mode.el
index 9fb48c7..a9a572d 100644
--- a/verilog-mode.el
+++ b/verilog-mode.el
@@ -4194,11 +4194,10 @@ With ARG, first kill any existing labels."
(verilog-backward-syntactic-ws)
(if (or (bolp)
(= (preceding-char) ?;)

  • (save-excursion
  • (progn
    (verilog-backward-token)
    (looking-at verilog-ends-re)))
    (progn
    (goto-char pt)
  •          (throw 'done t))
    
  •      (verilog-backward-token))))
    
  •          (throw 'done t)))))
    (verilog-forward-syntactic-ws)))
    


And here's the same profiling table after re-running against the modified code:

Function Name Call Count Elapsed Time Average Time
verilog-backward-token 45958 51.620183417 0.0011232034
verilog-at-constraint-p 13121 46.377667697 0.0035346138
verilog-beg-of-statement 6560 43.773631360 0.0066728096
verilog-indent-line 1 9.321540359 9.321540359
verilog-do-indent 1 9.319306 9.319306
verilog-beg-of-statement-1 2 9.318980949 4.6594904745
verilog-backward-syntactic-ws 98545 5.5213024270 5.602...e-05
verilog-skip-backward-comments 118227 5.3468814489 4.522...e-05
verilog-syntax-ppss 210108 4.0664912160 1.935...e-05
verilog-backward-ws&directives 19682 1.4135974839 7.182...e-05
verilog-forward-syntactic-ws 6562 0.4531344510 6.905...e-05
verilog-skip-forward-comment-p 6562 0.4098576799 6.245...e-05
verilog-in-attribute-p 6562 0.1666642440 2.539...e-05
verilog-re-search-backward 6563 0.0361106430 5.502...e-06


It appears that this optimization (i.e. don't do the same thing twice) offers about 50% reduction in processing time.  This is good, but not great.  Anecdotally, it seems feels like the longer the statement, the longer it takes to indent.  It feels like line N+1 takes about twice as long as line N when hitting TAB in these big multi-line statements.  A quick test shows it's actually about 3x:

line Function Call Count Elapsed Time Average Time
7 verilog-backward-token 24 0.006712392 0.000279683
8 verilog-backward-token 70 0.0147963029 0.0002113757
9 verilog-backward-token 200 0.1054797600 0.0005273988
10 verilog-backward-token 582 0.3333772310 0.0005728131
11 verilog-backward-token 1720 1.1867224759 0.0006899549
12 verilog-backward-token 5126 4.4657025630 0.0008711866
13 verilog-backward-token 15336 15.369902981 0.0010022106
14 verilog-backward-token 45958 53.268209736 0.0011590628
15 verilog-backward-token 137816 176.78015671 0.0012827259


The call count is always just under 3x, but the elapsed time is just over 3x.  Notice that the average time gets longer as more work is required.  Something is causing the effort to grow exponentially (actually, geometrically if I remember correctly).  Analysis of the top three functions (verilog-backward-token, verilog-at-constraint-p, verilog-beg-of-statement) shows circular calls (i.e. recursion) among these functions.  Throwing in a few print-statements here and there (along with stack-trace analysis using edebug) uncovers some of the problematic paths.

<br>

In the case of the chosen example, the bus-repetition operator {16{...}} causes deep resursion between verilog-backward-token and verilog-at-constraint-p.  Specifically, the "}}" triggers verilog-at-constraint-p to walk backward and check out the previous statement.  This in turn spawns excursions to check previous line, and the stack begins to grow.  Once complete, verilog-at-constraint-p returns and the previous line is re-analyzed.  In other words,  indenting on the first line of the statement parses only line 1.  Indenting the second line analyzes line ((2(1),(1)),(1)).  The third line analyzes (((3(2(1),1),(2(1),1),(1)),(2(1),1),(1)) (or something like that...)

<br>

Something needs to break the loop and restore a linear (or better) increase in complexity with each subsequent line.  A full re-architecture is beyond the scope of this analysis, but the following patch seems to provide a way of breaking the loop (at least for the selected example) without affecting indentation in the regression suite (Note: diff has whitespace minimized, hence the wacky indentation):

diff --git a/verilog-mode.el b/verilog-mode.el
index 6009b7a..65dcb47 100644
--- a/verilog-mode.el
+++ b/verilog-mode.el
@@ -6075,14 +6075,18 @@ Return >0 for nested struct."
(defun verilog-at-constraint-p ()
"If at the { of a constraint or coverpoint definition, return true, moving point to constraint."
(if (save-excursion

  • (let ((p (point)))
    (and
    (equal (char-after) ?{)
    (forward-list)
    (progn (backward-char 1)
    (verilog-backward-ws&directives)
  • (and
    (or (equal (char-before) ?{) ;; empty case
    (equal (char-before) ?;)
  •                (equal (char-before) ?\})))))
    
  •                (equal (char-before) ?\}))
    
  •                ;; skip what looks like bus repitition operator {#{
    
  •                (not (string-match "^{\\s-*[0-9]+\\s-*{" (buffer-substring p (point)))))))))
      (progn
        (let ( (pt (point)) (pass 0))
          (verilog-backward-ws&directives)
    


And here's the call-count table for verilog-backward-token for lines 7-15 of the source file:

line Function Call Count Elapsed Time Average Time
7 verilog-backward-token 18 0.011610509 0.0006450282
8 verilog-backward-token 30 0.0058237630 0.0001941254
9 verilog-backward-token 42 0.009163601 0.0002181809
10 verilog-backward-token 54 0.0051167460 9.475...e-05
11 verilog-backward-token 66 0.0060872910 9.223...e-05
12 verilog-backward-token 78 0.0068581500 8.792...e-05
13 verilog-backward-token 90 0.0088189500 9.798...e-05
14 verilog-backward-token 102 0.0097013330 9.511...e-05
15 verilog-backward-token 114 0.0170459359 0.0001495257



Selecting the entire buffer and indenting the entire thing at once only calls verilog-backward-token 3319 times with an Elapsed Time of only 0.6155.

<br>

The patches listed above are available on the branch https://github.com/acr4/verilog-mode/tree/bugfix-663-slow-indent which is branched from the original commit that introduced this regression.  For convenience, both commits have been merged to the current upstream master (https://github.com/veripool/verilog-mode/commit/ef977e0bf7d62cd2d2569aa3a058d7ec66b4bd83) on the branch https://github.com/acr4/verilog-mode/tree/merge-bugfix-663-for-wsnyder.  

@veripoolbot
Copy link
Collaborator Author


Original Redmine Comment
Author Name: Wilson Snyder (@wsnyder)
Original Date: 2014-11-06T00:21:22Z


Awesome! Pushed to trunk.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

1 participant