{"action":"created","issue":{"url":"https://api.github.com/repos/grpc/grpc-java/issues/2122","repository_url":"https://api.github.com/repos/grpc/grpc-java","labels_url":"https://api.github.com/repos/grpc/grpc-java/issues/2122/labels{/name}","comments_url":"https://api.github.com/repos/grpc/grpc-java/issues/2122/comments","events_url":"https://api.github.com/repos/grpc/grpc-java/issues/2122/events","html_url":"https://github.com/grpc/grpc-java/issues/2122","id":169179782,"number":2122,"title":"Contention in SerializingExecutor$TaskRunner.run","user":{"login":"carl-mastrangelo","id":8943572,"avatar_url":"https://avatars.githubusercontent.com/u/8943572?v=3","gravatar_id":"","url":"https://api.github.com/users/carl-mastrangelo","html_url":"https://github.com/carl-mastrangelo","followers_url":"https://api.github.com/users/carl-mastrangelo/followers","following_url":"https://api.github.com/users/carl-mastrangelo/following{/other_user}","gists_url":"https://api.github.com/users/carl-mastrangelo/gists{/gist_id}","starred_url":"https://api.github.com/users/carl-mastrangelo/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/carl-mastrangelo/subscriptions","organizations_url":"https://api.github.com/users/carl-mastrangelo/orgs","repos_url":"https://api.github.com/users/carl-mastrangelo/repos","events_url":"https://api.github.com/users/carl-mastrangelo/events{/privacy}","received_events_url":"https://api.github.com/users/carl-mastrangelo/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/grpc/grpc-java/labels/performance","name":"performance","color":"5319e7"}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":3,"created_at":"2016-08-03T16:51:13Z","updated_at":"2016-08-03T22:27:45Z","closed_at":null,"body":"Not sure why there is much contention here, but there does appear to be some.  This is very tiny compared to the rest of the other contention points.\r\n\r\n```\r\n      flat  flat%   sum%        cum   cum%\r\n     0.21s 0.0054% 97.67%   2853.93s 74.89%  io.grpc.internal.SerializingExecutor$TaskRunner.run SerializingExecutor.java:142\r\n\r\n```"},"comment":{"url":"https://api.github.com/repos/grpc/grpc-java/issues/comments/237394817","html_url":"https://github.com/grpc/grpc-java/issues/2122#issuecomment-237394817","issue_url":"https://api.github.com/repos/grpc/grpc-java/issues/2122","id":237394817,"user":{"login":"pgrosu","id":6555937,"avatar_url":"https://avatars.githubusercontent.com/u/6555937?v=3","gravatar_id":"","url":"https://api.github.com/users/pgrosu","html_url":"https://github.com/pgrosu","followers_url":"https://api.github.com/users/pgrosu/followers","following_url":"https://api.github.com/users/pgrosu/following{/other_user}","gists_url":"https://api.github.com/users/pgrosu/gists{/gist_id}","starred_url":"https://api.github.com/users/pgrosu/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/pgrosu/subscriptions","organizations_url":"https://api.github.com/users/pgrosu/orgs","repos_url":"https://api.github.com/users/pgrosu/repos","events_url":"https://api.github.com/users/pgrosu/events{/privacy}","received_events_url":"https://api.github.com/users/pgrosu/received_events","type":"User","site_admin":false},"created_at":"2016-08-03T22:27:45Z","updated_at":"2016-08-03T22:27:45Z","body":"Here's a little program to demo this, but I'm not getting anywhere as high as 210 milliseconds, but it does increase with the number of threads.\r\n\r\n```Java\r\nclass MonitoredLock {\r\n   public void print(){\r\n    try {\r\n        System.out.println( \"...Lock is Synchronized...\" );\r\n     } catch (Exception e) {\r\n         System.out.println(\" Thread is interrupted. \");\r\n     }\r\n   }\r\n}\r\n\r\nclass SynchronizedThread extends Thread {\r\n\r\n   private Thread thread;\r\n   private String threadName;\r\n   int semaphore = 10;\r\n   MonitoredLock  ML;\r\n\r\n   SynchronizedThread( String name,  MonitoredLock refML){\r\n       threadName = name;\r\n       ML = refML;\r\n   }\r\n\r\n   public void run() {\r\n     while ( semaphore > 0 ) {\r\n       long tick = System.currentTimeMillis();\r\n       synchronized (ML) {\r\n          ML.print();\r\n          long elapsed = System.currentTimeMillis() - tick;\r\n          System.out.println(\"Thread \" +  threadName + \" -> elapsed during sync: \" + elapsed );\r\n       }\r\n       long elapsed = System.currentTimeMillis() - tick;\r\n       System.out.println(\"Thread \" +  threadName + \" -> elapsed outside sync: \" + elapsed );\r\n       semaphore = semaphore - 1;\r\n      }\r\n   }\r\n\r\n   public void start ()\r\n   {\r\n      System.out.println(\"Starting \" +  threadName );\r\n      if (thread == null)\r\n      {\r\n         thread = new Thread (this, threadName);\r\n         thread.start ();\r\n      }\r\n   }\r\n\r\n}\r\n\r\npublic class SynchronizedTest {\r\n   public static void main(String args[]) {\r\n\r\n      MonitoredLock ML = new MonitoredLock();\r\n\r\n      SynchronizedThread T1 = new SynchronizedThread( \" 1 \", ML );\r\n      SynchronizedThread T2 = new SynchronizedThread( \" 2 \", ML );\r\n      SynchronizedThread T3 = new SynchronizedThread( \" 3 \", ML );\r\n      SynchronizedThread T4 = new SynchronizedThread( \" 4 \", ML );\r\n\r\n      T1.start();\r\n      T2.start();\r\n      T3.start();\r\n      T4.start();\r\n\r\n      try {\r\n         T1.join();\r\n         T2.join();\r\n         T3.join();\r\n         T4.join();\r\n      } catch( Exception e) {\r\n         System.out.println(\"Interrupted\");\r\n      }\r\n   }\r\n}\r\n```\r\nBelow is the result of running it:\r\n\r\n```\r\n> javac SynchronizedTest.java && java SynchronizedTest\r\nStarting  1\r\nStarting  2\r\n...Lock is Synchronized...\r\nStarting  3\r\nThread  1  -> elapsed during sync: 0\r\n...Lock is Synchronized...\r\nStarting  4\r\nThread  3  -> elapsed during sync: 0\r\nThread  1  -> elapsed outside sync: 1\r\n...Lock is Synchronized...\r\nThread  3  -> elapsed outside sync: 0\r\nThread  4  -> elapsed during sync: 1\r\n...Lock is Synchronized...\r\nThread  4  -> elapsed outside sync: 1\r\nThread  2  -> elapsed during sync: 3\r\n...Lock is Synchronized...\r\nThread  2  -> elapsed outside sync: 3\r\nThread  4  -> elapsed during sync: 0\r\n...Lock is Synchronized...\r\nThread  4  -> elapsed outside sync: 1\r\nThread  3  -> elapsed during sync: 2\r\n...Lock is Synchronized...\r\nThread  3  -> elapsed outside sync: 2\r\nThread  1  -> elapsed during sync: 2\r\n...Lock is Synchronized...\r\nThread  1  -> elapsed outside sync: 3\r\nThread  3  -> elapsed during sync: 0\r\n...Lock is Synchronized...\r\nThread  3  -> elapsed outside sync: 0\r\nThread  4  -> elapsed during sync: 1\r\n...Lock is Synchronized...\r\nThread  4  -> elapsed outside sync: 2\r\nThread  2  -> elapsed during sync: 3\r\n...Lock is Synchronized...\r\nThread  2  -> elapsed outside sync: 3\r\nThread  4  -> elapsed during sync: 1\r\n...Lock is Synchronized...\r\nThread  4  -> elapsed outside sync: 1\r\nThread  3  -> elapsed during sync: 1\r\n...Lock is Synchronized...\r\nThread  3  -> elapsed outside sync: 2\r\nThread  1  -> elapsed during sync: 3\r\n...Lock is Synchronized...\r\nThread  1  -> elapsed outside sync: 3\r\nThread  3  -> elapsed during sync: 0\r\n...Lock is Synchronized...\r\nThread  3  -> elapsed outside sync: 1\r\nThread  4  -> elapsed during sync: 2\r\n...Lock is Synchronized...\r\nThread  4  -> elapsed outside sync: 2\r\nThread  2  -> elapsed during sync: 3\r\n...Lock is Synchronized...\r\nThread  2  -> elapsed outside sync: 3\r\nThread  4  -> elapsed during sync: 0\r\n...Lock is Synchronized...\r\nThread  4  -> elapsed outside sync: 1\r\nThread  3  -> elapsed during sync: 2\r\n...Lock is Synchronized...\r\nThread  1  -> elapsed during sync: 3\r\nThread  1  -> elapsed outside sync: 3\r\nThread  3  -> elapsed outside sync: 3\r\n...Lock is Synchronized...\r\nThread  4  -> elapsed during sync: 2\r\n...Lock is Synchronized...\r\nThread  4  -> elapsed outside sync: 3\r\nThread  2  -> elapsed during sync: 4\r\n...Lock is Synchronized...\r\nThread  2  -> elapsed outside sync: 5\r\nThread  4  -> elapsed during sync: 1\r\n...Lock is Synchronized...\r\nThread  4  -> elapsed outside sync: 2\r\nThread  3  -> elapsed during sync: 3\r\n...Lock is Synchronized...\r\nThread  3  -> elapsed outside sync: 4\r\nThread  1  -> elapsed during sync: 4\r\n...Lock is Synchronized...\r\nThread  1  -> elapsed outside sync: 5\r\nThread  3  -> elapsed during sync: 1\r\n...Lock is Synchronized...\r\nThread  3  -> elapsed outside sync: 1\r\nThread  4  -> elapsed during sync: 2\r\n...Lock is Synchronized...\r\nThread  4  -> elapsed outside sync: 3\r\nThread  2  -> elapsed during sync: 4\r\n...Lock is Synchronized...\r\nThread  2  -> elapsed outside sync: 4\r\nThread  4  -> elapsed during sync: 1\r\n...Lock is Synchronized...\r\nThread  4  -> elapsed outside sync: 1\r\nThread  3  -> elapsed during sync: 1\r\n...Lock is Synchronized...\r\nThread  3  -> elapsed outside sync: 2\r\nThread  1  -> elapsed during sync: 3\r\n...Lock is Synchronized...\r\nThread  1  -> elapsed outside sync: 4\r\nThread  3  -> elapsed during sync: 1\r\n...Lock is Synchronized...\r\nThread  3  -> elapsed outside sync: 1\r\nThread  2  -> elapsed during sync: 3\r\n...Lock is Synchronized...\r\nThread  2  -> elapsed outside sync: 3\r\nThread  1  -> elapsed during sync: 1\r\n...Lock is Synchronized...\r\nThread  1  -> elapsed outside sync: 2\r\nThread  2  -> elapsed during sync: 0\r\n...Lock is Synchronized...\r\nThread  2  -> elapsed outside sync: 0\r\nThread  1  -> elapsed during sync: 1\r\n...Lock is Synchronized...\r\nThread  1  -> elapsed outside sync: 1\r\nThread  2  -> elapsed during sync: 1\r\n...Lock is Synchronized...\r\nThread  2  -> elapsed outside sync: 1\r\nThread  1  -> elapsed during sync: 1\r\n...Lock is Synchronized...\r\nThread  1  -> elapsed outside sync: 1\r\nThread  2  -> elapsed during sync: 1\r\n...Lock is Synchronized...\r\nThread  2  -> elapsed outside sync: 1\r\nThread  1  -> elapsed during sync: 1\r\n...Lock is Synchronized...\r\nThread  1  -> elapsed outside sync: 1\r\nThread  2  -> elapsed during sync: 0\r\nThread  2  -> elapsed outside sync: 1\r\n> \r\n```\r\n\r\nBy running only two threads, naturally the elapsed times are smaller:\r\n\r\n```\r\n> java SynchronizedTest\r\nStarting  1\r\nStarting  2\r\n...Lock is Synchronized...\r\nThread  1  -> elapsed during sync: 1\r\n...Lock is Synchronized...\r\nThread  1  -> elapsed outside sync: 1\r\nThread  2  -> elapsed during sync: 0\r\n...Lock is Synchronized...\r\nThread  2  -> elapsed outside sync: 1\r\nThread  1  -> elapsed during sync: 1\r\n...Lock is Synchronized...\r\nThread  1  -> elapsed outside sync: 2\r\nThread  2  -> elapsed during sync: 1\r\n...Lock is Synchronized...\r\nThread  2  -> elapsed outside sync: 2\r\nThread  1  -> elapsed during sync: 1\r\n...Lock is Synchronized...\r\nThread  1  -> elapsed outside sync: 1\r\nThread  2  -> elapsed during sync: 0\r\n...Lock is Synchronized...\r\nThread  2  -> elapsed outside sync: 1\r\nThread  1  -> elapsed during sync: 0\r\n...Lock is Synchronized...\r\nThread  1  -> elapsed outside sync: 0\r\nThread  2  -> elapsed during sync: 1\r\n...Lock is Synchronized...\r\nThread  2  -> elapsed outside sync: 1\r\nThread  1  -> elapsed during sync: 0\r\n...Lock is Synchronized...\r\nThread  1  -> elapsed outside sync: 1\r\nThread  2  -> elapsed during sync: 1\r\n...Lock is Synchronized...\r\nThread  2  -> elapsed outside sync: 1\r\nThread  1  -> elapsed during sync: 0\r\n...Lock is Synchronized...\r\nThread  1  -> elapsed outside sync: 1\r\nThread  2  -> elapsed during sync: 0\r\n...Lock is Synchronized...\r\nThread  2  -> elapsed outside sync: 0\r\nThread  1  -> elapsed during sync: 1\r\n...Lock is Synchronized...\r\nThread  1  -> elapsed outside sync: 1\r\nThread  2  -> elapsed during sync: 0\r\n...Lock is Synchronized...\r\nThread  2  -> elapsed outside sync: 1\r\nThread  1  -> elapsed during sync: 1\r\n...Lock is Synchronized...\r\nThread  1  -> elapsed outside sync: 1\r\nThread  2  -> elapsed during sync: 0\r\n...Lock is Synchronized...\r\nThread  2  -> elapsed outside sync: 1\r\nThread  1  -> elapsed during sync: 0\r\n...Lock is Synchronized...\r\nThread  1  -> elapsed outside sync: 1\r\nThread  2  -> elapsed during sync: 1\r\n...Lock is Synchronized...\r\nThread  2  -> elapsed outside sync: 1\r\nThread  1  -> elapsed during sync: 1\r\n...Lock is Synchronized...\r\nThread  1  -> elapsed outside sync: 1\r\nThread  2  -> elapsed during sync: 0\r\nThread  2  -> elapsed outside sync: 1\r\n>\r\n```"}}
{"actor":{"display_login":"pgrosu"}}