{"action":"created","issue":{"url":"https://api.github.com/repos/letscontrolit/ESPEasy/issues/1557","repository_url":"https://api.github.com/repos/letscontrolit/ESPEasy","labels_url":"https://api.github.com/repos/letscontrolit/ESPEasy/issues/1557/labels{/name}","comments_url":"https://api.github.com/repos/letscontrolit/ESPEasy/issues/1557/comments","events_url":"https://api.github.com/repos/letscontrolit/ESPEasy/issues/1557/events","html_url":"https://github.com/letscontrolit/ESPEasy/issues/1557","id":339345303,"node_id":"MDU6SXNzdWUzMzkzNDUzMDM=","number":1557,"title":"[Timing] Overview of timing issues per plugin","user":{"login":"TD-er","id":3751318,"node_id":"MDQ6VXNlcjM3NTEzMTg=","avatar_url":"https://avatars3.githubusercontent.com/u/3751318?v=4","gravatar_id":"","url":"https://api.github.com/users/TD-er","html_url":"https://github.com/TD-er","followers_url":"https://api.github.com/users/TD-er/followers","following_url":"https://api.github.com/users/TD-er/following{/other_user}","gists_url":"https://api.github.com/users/TD-er/gists{/gist_id}","starred_url":"https://api.github.com/users/TD-er/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/TD-er/subscriptions","organizations_url":"https://api.github.com/users/TD-er/orgs","repos_url":"https://api.github.com/users/TD-er/repos","events_url":"https://api.github.com/users/TD-er/events{/privacy}","received_events_url":"https://api.github.com/users/TD-er/received_events","type":"User","site_admin":false},"labels":[{"id":855470727,"node_id":"MDU6TGFiZWw4NTU0NzA3Mjc=","url":"https://api.github.com/repos/letscontrolit/ESPEasy/labels/Category:%20Stabiliy","name":"Category: Stabiliy","color":"5319e7","default":false},{"id":257820027,"node_id":"MDU6TGFiZWwyNTc4MjAwMjc=","url":"https://api.github.com/repos/letscontrolit/ESPEasy/labels/Status:%20In%20Progress","name":"Status: In Progress","color":"c2e0c6","default":false},{"id":855162107,"node_id":"MDU6TGFiZWw4NTUxNjIxMDc=","url":"https://api.github.com/repos/letscontrolit/ESPEasy/labels/Status:%20Needs%20Info","name":"Status: Needs Info","color":"bfdadc","default":false}],"state":"open","locked":false,"assignee":{"login":"TD-er","id":3751318,"node_id":"MDQ6VXNlcjM3NTEzMTg=","avatar_url":"https://avatars3.githubusercontent.com/u/3751318?v=4","gravatar_id":"","url":"https://api.github.com/users/TD-er","html_url":"https://github.com/TD-er","followers_url":"https://api.github.com/users/TD-er/followers","following_url":"https://api.github.com/users/TD-er/following{/other_user}","gists_url":"https://api.github.com/users/TD-er/gists{/gist_id}","starred_url":"https://api.github.com/users/TD-er/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/TD-er/subscriptions","organizations_url":"https://api.github.com/users/TD-er/orgs","repos_url":"https://api.github.com/users/TD-er/repos","events_url":"https://api.github.com/users/TD-er/events{/privacy}","received_events_url":"https://api.github.com/users/TD-er/received_events","type":"User","site_admin":false},"assignees":[{"login":"TD-er","id":3751318,"node_id":"MDQ6VXNlcjM3NTEzMTg=","avatar_url":"https://avatars3.githubusercontent.com/u/3751318?v=4","gravatar_id":"","url":"https://api.github.com/users/TD-er","html_url":"https://github.com/TD-er","followers_url":"https://api.github.com/users/TD-er/followers","following_url":"https://api.github.com/users/TD-er/following{/other_user}","gists_url":"https://api.github.com/users/TD-er/gists{/gist_id}","starred_url":"https://api.github.com/users/TD-er/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/TD-er/subscriptions","organizations_url":"https://api.github.com/users/TD-er/orgs","repos_url":"https://api.github.com/users/TD-er/repos","events_url":"https://api.github.com/users/TD-er/events{/privacy}","received_events_url":"https://api.github.com/users/TD-er/received_events","type":"User","site_admin":false}],"milestone":null,"comments":11,"created_at":"2018-07-09T08:06:38Z","updated_at":"2018-07-15T14:29:23Z","closed_at":null,"author_association":"CONTRIBUTOR","body":"Starting with build [mega-20180708](https://github.com/letscontrolit/ESPEasy/releases/tag/mega-20180708) some timing statistics will be logged.\r\nThese can only be seen when looking at the log via serial port. (web log view will be added too, but for now doesn't work, that's another issue)\r\nLoglevel should be at Debug level.\r\n\r\nThese logs will indicate the min/avg/max durations in usec used by several calls to plugins.\r\nA few examples already shown [here](https://github.com/letscontrolit/ESPEasy/issues/914#issuecomment-403365311).\r\n\r\n```\r\n70772995 : LoopStats: shortestLoop: 46 longestLoop: 1058298 avgLoopDuration: 90.23 systemTimerDuration: 25.35 systemTimerCalls: 31 loopCounterMax: 652173 loopCounterLast: 324928 countFindPluginId: 0\r\n70773002 : PluginStats P_22_Extra IO - PCA9685 READ                 Count: 1 Avg/min/max 15.00/15/15 usec\r\n70773011 : PluginStats P_22_Extra IO - PCA9685 ONCE_A_SECOND        Count: 30 Avg/min/max 15.87/11/27 usec\r\n70773020 : PluginStats P_22_Extra IO - PCA9685 TEN_PER_SECOND       Count: 300 Avg/min/max 12.05/3/38 usec\r\n70773029 : PluginStats P_22_Extra IO - PCA9685 WRITE                Count: 10 Avg/min/max 453.00/387/796 usec\r\n70773039 : PluginStats P_22_Extra IO - PCA9685 FIFTY_PER_SECOND     Count: 1489 Avg/min/max 15.60/10/46 usec\r\n70773048 : Plugin call 50 p/s   stats: Count: 1489 Avg/min/max 587.28/504/922 usec\r\n70773056 : Plugin call 10 p/s   stats: Count: 300 Avg/min/max 538.97/500/857 usec\r\n70773063 : Plugin call 10 p/s U stats: Count: 300 Avg/min/max 3551.89/3204/3978 usec\r\n70773070 : Plugin call  1 p/s   stats: Count: 30 Avg/min/max 9547.20/1782/203298 usec\r\n70773078 : checkSensors()       stats: Count: 30 Avg/min/max 882.50/637/2346 usec\r\n70773085 : WD   : Uptime 1179 ConnectFailures 2 FreeMem 13424\r\n```\r\n\r\nSome help in reading this:\r\nData is collected over 30 seconds time and after that this report is generated.\r\nFor example 300 calls to \"Plugin call 10 p/s\" is just perfect.\r\nTo be able to serve all calls to the \"Plugin call 50 p/s\", no other call should take more than 20 msec (20'000 usec)\r\nAn occasional peak is not really a problem, but average values over 20 msec may prevent calls to 1/50th sec calls in due time.\r\nThe same for calls taking over 100 msec, which may prevent 1/10th second calls.\r\n\r\nNot many plugins use the 1/50th call, but when they do, they are probably time critical.\r\n\r\nThe idea of this issue is to collect data on plugins that may exceed these timing restrictions.\r\nFor example reading the buffer from software serial is rather timing critical.\r\n\r\nI will later add the same stats to calls to controllers. For now only plugin (task) calls are processed."},"comment":{"url":"https://api.github.com/repos/letscontrolit/ESPEasy/issues/comments/405095786","html_url":"https://github.com/letscontrolit/ESPEasy/issues/1557#issuecomment-405095786","issue_url":"https://api.github.com/repos/letscontrolit/ESPEasy/issues/1557","id":405095786,"node_id":"MDEyOklzc3VlQ29tbWVudDQwNTA5NTc4Ng==","user":{"login":"clumsy-stefan","id":32835100,"node_id":"MDQ6VXNlcjMyODM1MTAw","avatar_url":"https://avatars0.githubusercontent.com/u/32835100?v=4","gravatar_id":"","url":"https://api.github.com/users/clumsy-stefan","html_url":"https://github.com/clumsy-stefan","followers_url":"https://api.github.com/users/clumsy-stefan/followers","following_url":"https://api.github.com/users/clumsy-stefan/following{/other_user}","gists_url":"https://api.github.com/users/clumsy-stefan/gists{/gist_id}","starred_url":"https://api.github.com/users/clumsy-stefan/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/clumsy-stefan/subscriptions","organizations_url":"https://api.github.com/users/clumsy-stefan/orgs","repos_url":"https://api.github.com/users/clumsy-stefan/repos","events_url":"https://api.github.com/users/clumsy-stefan/events{/privacy}","received_events_url":"https://api.github.com/users/clumsy-stefan/received_events","type":"User","site_admin":false},"created_at":"2018-07-15T14:29:23Z","updated_at":"2018-07-15T14:29:23Z","author_association":"CONTRIBUTOR","body":"@s0170071 just tried to read a bit about Serial communication, what I can't find is any documentation that Serial.available will return 128 on buffer overflows... Especially as SoftwareSerial uses a ringbuffer of 64 bytes and discards everything after that. can you point me to some useful information on such an implementation?\r\n"}}
{"actor":{"display_login":"clumsy-stefan"}}