|
fbtracemgr: разные мелкие вопросы
|
|||
---|---|---|---|
#18+
ТаблоидСекундомер показал, к примеру, 5.94 сек, сумма же значений времени вып-я в трейсе равна 8300 мс.пардон муа, глупость я сморозил :-[. Один из... (страшно даже сказать кто) показал в личке элементарный пример, объясняющий то, что суммарное время по трейсу больше, чем "по часам": 1. start select from sp 2. start select from sp2 3. finish select from sp2, t = 10 4.finish from sp, t = 20 sp вызывает sp2; общее время вып-я будет 20, а не бездумно просуммированное 30. В общем, вопрос про расхождение в суммах снят. ... |
|||
:
Нравится:
Не нравится:
|
|||
06.03.2012, 18:36 |
|
fbtracemgr: разные мелкие вопросы
|
|||
---|---|---|---|
#18+
Что ж, продолжим разговор :-) session #1 : мониторное окно, в нём - старт трейса с параметрами: Код: plaintext 1. 2. 3. 4. 5. 6. 7. 8. 9. 10. 11. 12. 13. 14. 15. 16. 17. 18. 19. 20. 21. 22.
session #2 : isql-окно с неким тяжелым запросом, которое либо срубается "крестиком", либо обламывается командой delete from mon$attachments (из третьего окна), либо прерывается банальным Ctrl-Break: Код: plaintext 1. 2. 3.
Trace-1: Код: plaintext 1. 2. 3. 4. 5. 6. 7. 8. 9. 10. 11. 12. 13. 14. 15. 16. 17. 18. 19. 20. 21. 22. 23. 24. 25. 26. 27. 28. 29. 30. 31. 32. 33. 34. 35. 36. 37. 38. 39. 40. 41. 42. 43. 44. 45. 46. 47. 48. 49. 50. 51. 52. 53. 54. 55. 56. 57. 58. 59. 60. 61. 62. 63. 64. 65. 66. 67. 68. 69. 70. 71. 72. 73. 74. 75. 76. 77. 78. 79. 80. 81. 82. 83. 84. 85. 86. 87. 88. 89. 90. 91. 92. 93. 94. 95. 96. 97. 98. 99. 100. 101. 102. 103. 104. 105. 106. 107. 108. 109. 110. 111. 112. 113. 114. 115. 116. 117. 118. 119. 120. 121. 122. 123. 124. 125. 126. 127. 128. 129. 130. 131. 132. 133. 134. 135. 136. 137. 138. 139. 140. 141. 142. 143. 144. 145.
И второй эксперимент: в том же окне-молотилке вместо select count(*) выполняем: Код: plaintext 1.
Затем прерываем его работу через delete from mon$attachments where mon$attachment_id<>current_connection; commit; В трейсе будет видно уже НЕнулевое время, около 7 сек. Но оно намного меньше, чем то, что фактически прошло! В нижеприведенном логе видно, что: EXECUTE_STATEMENT_START случился в 2012-05-10T23:59:02.3280 EXECUTE_STATEMENT_FINISH произошёл в 2012-05-10T23:59:48.0310 -- таким обр, прошло 45 сек. А в трейсе говорится, что молотьба шла якобы 6.9 сек. Trace-2: Код: plaintext 1. 2. 3. 4. 5. 6. 7. 8. 9. 10. 11. 12. 13. 14. 15. 16. 17. 18. 19. 20. 21. 22. 23. 24. 25. 26. 27. 28. 29. 30. 31. 32. 33. 34. 35. 36. 37. 38. 39. 40. 41. 42. 43. 44. 45. 46. 47. 48. 49. 50. 51. 52. 53. 54. 55. 56. 57. 58. 59. 60. 61. 62. 63. 64. 65. 66. 67. 68. 69. 70. 71. 72. 73. 74. 75. 76. 77. 78. 79. 80. 81. 82. 83. 84. 85. 86. 87. 88. 89. 90. 91. 92. 93. 94. 95. 96. 97. 98. 99. 100. 101. 102. 103. 104. 105. 106. 107. 108. 109. 110. 111. 112. 113. 114. 115. 116. 117. 118. 119. 120. 121. 122. 123. 124. 125. 126. 127. 128. 129. 130. 131. 132. 133. 134. 135. 136. 137. 138. 139. 140. 141. 142. 143. 144. 145. 146. 147. 148. 149. 150. 151. 152. 153. 154. 155. 156. 157. 158. 159. 160. 161. 162. 163. 164. 165. 166. 167. 168. 169. 170. 171. 172. 173. 174. 175. 176. 177. 178. 179. 180. 181. 182. 183. 184. 185. 186. 187. 188. 189. 190. 191. 192. 193. 194. 195. 196. 197. 198. 199. 200. 201. 202. 203. 204. 205. 206. 207. 208. 209. 210. 211. 212. 213. 214. 215. 216. 217. 218. 219. 220. 221. 222. 223. 224. 225. 226. 227. 228. 229. 230. 231. 232. 233. 234. 235. 236. 237. 238. 239. 240. 241. 242. 243. 244. 245. 246. 247. 248. 249. 250. 251. 252. 253. 254. 255. 256. 257. 258. 259. 260. 261. 262. 263. 264. 265.
... |
|||
:
Нравится:
Не нравится:
|
|||
11.05.2012, 00:11 |
|
fbtracemgr: разные мелкие вопросы
|
|||
---|---|---|---|
#18+
ТаблоидВопрос-1: почему время выполнения прерванного запроса = 0 мс ?Потому что бага ТаблоидВопрос-2: почему время в статистике запроса, хоть и ненулевое, но совершенно нереальное ?Потому что трейс считает только время, проведенное в движке. А isql учитывает : - время на трансфер данных между сетевым сервером и движком - время на трансфер данных между приложениями - время на обработку данных самим isql ... |
|||
:
Нравится:
Не нравится:
|
|||
11.05.2012, 01:58 |
|
fbtracemgr: разные мелкие вопросы
|
|||
---|---|---|---|
#18+
hvladТаблоидВопрос-2: почему время в статистике запроса, хоть и ненулевое, но совершенно нереальное ?Потому что трейс считает только время, проведенное в движке. А isql учитывает : - время на трансфер данных между сетевым сервером и движком - время на трансфер данных между приложениями - время на обработку данных самим isqlДа, но данных в этой таблице (rdb$fields) - кот накакал: not_null значений во всех блоб-полях только 4, и все - по несколько байт; два (var)char-поля из трёх (query_name, edit_string) - все null. Остальные поля - smallint, причем только 4 столбца заполнены целиком (field_len, field_scale, field_type & system_flag). Остальные - опять-таки по большей части null'ы. Повторил эксперимент, но для таблицы с единственным smallint-полем и 120 строками. DDL: Код: plaintext 1. 2. 3. 4. 5.
Test: Код: plaintext 1. 2. 3.
Теперь ждём три минуты , затем прерываем из другого окна по delete from mon$attachments. Смотрим после этого в трейс: он показывает, что время "в движке" составило всего 48 сек ! И это при том, что данные таблицы никуда на самом деле не выводились (всё перенаправлялось в nul). Передача значений smallint-поля (это же два байта всего) заняла в два с лишним раза больше, чем их извлечение движком... Код: plaintext 1. 2. 3. 4. 5. 6. 7. 8. 9. 10. 11. 12. 13. 14. 15. 16. 17. 18. 19. 20. 21. 22. 23. 24. 25. 26. 27. 28. 29. 30. 31. 32. 33. 34. 35. 36. 37. 38. 39. 40. 41. 42. 43. 44. 45. 46. 47. 48. 49. 50. 51. 52. 53. 54. 55. 56. 57. 58. 59. 60. 61. 62. 63. 64. 65. 66. 67. 68. 69. 70. 71. 72. 73. 74. 75. 76. 77. 78. 79. 80. 81. 82. 83. 84. 85. 86. 87. 88. 89. 90. 91. 92. 93. 94. 95. 96. 97. 98. 99. 100. 101. 102. 103. 104. 105. 106. 107. 108. 109. 110. 111. 112. 113. 114. 115. 116. 117. 118. 119. 120. 121. 122. 123. 124. 125. 126. 127. 128. 129. 130. 131. 132. 133. 134. 135. 136. 137. 138. 139. 140. 141. 142. 143. 144. 145. 146. 147. 148. 149. 150. 151. 152. 153. 154. 155. 156. 157. 158. 159. 160. 161. 162. 163. 164. 165. 166. 167. 168. 169. 170. 171. 172. 173. 174. 175. 176. 177. 178. 179. 180. 181. 182. 183. 184. 185. 186. 187. 188. 189. 190. 191. 192. 193. 194. 195. 196. 197. 198. 199. 200. 201. 202. 203. 204. 205. 206. 207. 208. 209. 210. 211. 212. 213. 214. 215. 216. 217. 218. 219. 220. 221. 222. 223. 224. 225. 226. 227. 228. 229. 230. 231.
PS. ПОЛУОФФ. gstat -r -t для rdb$-таблиц не работает, что ли ? Код: plaintext 1. 2. 3. 4. 5. 6. 7. 8. 9. 10. 11. 12. 13. 14. 15. 16.
... |
|||
:
Нравится:
Не нравится:
|
|||
11.05.2012, 08:56 |
|
fbtracemgr: разные мелкие вопросы
|
|||
---|---|---|---|
#18+
ТаблоидТеперь ждём три минуты , затем прерываем из другого окна по delete from mon$attachments. Смотрим после этого в трейс: он показывает, что время "в движке" составило всего 48 сек ! И это при том, что данные таблицы никуда на самом деле не выводились (всё перенаправлялось в nul)Ага, не выводились. Из движка в y-valve, из y-valve в сетевой редиректор, потом через сеть потом в клиентский сетевой редиректор, потом в клиентский y-valve, потом в isql, потом в строку, потом в nul - мало ? Кроме того, я же сказал, что при прерывании запроса время не считается правильно. ТаблоидПередача значений smallint-поля (это же два байта всего) заняла в два с лишним раза больше, чем их извлечение движком...Ну так движок рулит, что плохого ? :) ... |
|||
:
Нравится:
Не нравится:
|
|||
11.05.2012, 11:17 |
|
fbtracemgr: разные мелкие вопросы
|
|||
---|---|---|---|
#18+
Таблоидgstat -r -t для rdb$-таблиц не работает, что ли ?Борманов спрашивай, они это делали... ... |
|||
:
Нравится:
Не нравится:
|
|||
11.05.2012, 11:18 |
|
fbtracemgr: разные мелкие вопросы
|
|||
---|---|---|---|
#18+
hvladИз движка в y-valve, из y-valve в сетевой редиректор, потом через сеть потом в клиентский сетевой редиректор, потом в клиентский y-valve, потом в isql, потом в строку, потом в nul - мало ?Судя по перечисленному (5 посредников) - не мало, конечно. Но всё равно неожиданно сильная "помеха" от них. Надо будет проверить еще и DML, а не только селект. ... |
|||
:
Нравится:
Не нравится:
|
|||
11.05.2012, 12:16 |
|
fbtracemgr: разные мелкие вопросы
|
|||
---|---|---|---|
#18+
hvladКроме того, я же сказал, что при прерывании запроса время не считается правильно.Оно странно выглядит также и в следующем случае: Код: plaintext 1. 2. 3. 4.
Трейс: Код: plaintext 1. 2. 3. 4. 5. 6. 7. 8. 9. 10. 11. 12. 13. 14. 15. 16. 17. 18. 19. 20. 21. 22. 23. 24. 25. 26. 27. 28. 29. 30. 31. 32. 33. 34. 35. 36. 37. 38. 39. 40. 41. 42. 43. 44. 45. 46. 47. 48. 49. 50. 51. 52. 53. 54. 55. 56. 57. 58. 59. 60. 61. 62. 63. 64. 65. 66. 67. 68. 69. 70. 71. 72. 73. 74. 75. 76. 77. 78. 79. 80. 81. 82. 83. 84. 85. 86. 87. 88. 89. 90. 91. 92. 93. 94. 95. 96. 97. 98. 99. 100. 101. 102. 103. 104. 105. 106. 107. 108. 109. 110. 111. 112. 113. 114. 115. 116. 117. 118. 119. 120. 121.
А теперь смотрим на значения моментов времени начала и окончания вып-я запроса, те что я выделил синим цветом: Код: plaintext 1. 2. 3. 4. 5.
... |
|||
:
Нравится:
Не нравится:
|
|||
11.05.2012, 17:01 |
|
fbtracemgr: разные мелкие вопросы
|
|||
---|---|---|---|
#18+
Таблоид, почему бы тебе вместо Код: sql 1.
не сделать Код: sql 1.
? Уберешь время передачи данных клиенту, при таком раскладе практически все время должно быть временем отработки запроса в движке. ... |
|||
:
Нравится:
Не нравится:
|
|||
11.05.2012, 17:19 |
|
fbtracemgr: разные мелкие вопросы
|
|||
---|---|---|---|
#18+
Dzirtпри таком раскладе практически все время должно быть временем отработки запроса в движке.Оно понятно, только "одиночный count" (одна строка с результатом) гораздо реже возвращается, чем сами данные. А при передаче данных даже без сети, как выясняется, эти данным приходится через тучу посредников проходить. И даже при отключке TCP-стека, т.е. работе по XNET , ощутимо влияние этих посредников: трейс говорит, что без tcp-стека "в движке" всё выполнялось 28.3 сек, а на самом деле это длилось 58,3 сек: Код: plaintext 1. 2. 3. 4. 5. 6. 7. 8. 9. 10. 11. 12. 13. 14. 15. 16. 17. 18. 19. 20. 21. 22. 23. 24. 25. 26. 27. 28. 29. 30. 31. 32. 33. 34. 35. 36. 37. 38. 39. 40. 41. 42. 43. 44. 45. 46. 47. 48. 49. 50.
Код: plaintext 1. 2. 3. 4. 5.
Настоящая тёмная материя - это y_valve и редиректор. ... |
|||
:
Нравится:
Не нравится:
|
|||
11.05.2012, 17:42 |
|
fbtracemgr: разные мелкие вопросы
|
|||
---|---|---|---|
#18+
DzirtТаблоид, почему бы тебе вместо Код: sql 1.
не сделать Код: sql 1.
Сделал и это (только добавил еще одну таблицу в кросс-джойн, а то с тремя очень быстро получилось). Итог: данные статистики трейса практически совпали с разницей моментов execute_statement_start & _finish: Код: plaintext 1. 2. 3. 4. 5. 6. 7. 8. 9. 10. 11. 12. 13. 14. 15. 16. 17. 18. 19. 20. 21. 22. 23. 24. 25. 26. 27. 28. 29. 30. 31. 32. 33. 34. 35. 36. 37. 38. 39. 40. 41. 42. 43. 44.
Check: Код: plaintext 1. 2. 3. 4. 5.
... |
|||
:
Нравится:
Не нравится:
|
|||
11.05.2012, 17:48 |
|
fbtracemgr: разные мелкие вопросы
|
|||
---|---|---|---|
#18+
Таблоиддаже при отключке TCP-стека, т.е. работе по XNET, ощутимо влияние этих посредников Потому что в XNET задействована точно та же самая цепочка, что и в TCP. Posted via ActualForum NNTP Server 1.5 ... |
|||
:
Нравится:
Не нравится:
|
|||
11.05.2012, 18:09 |
|
fbtracemgr: разные мелкие вопросы
|
|||
---|---|---|---|
#18+
Давно мечтал спросить, да всё как-то стеснялся. Вот фрагмент трейса: Код: plaintext 1. 2. 3. 4. 5. 6. 7. 8. 9. 10. 11. 12.
1) Что указывается в скобках ? Почему это число всё время одинаковое во всех блоках ? 2) Можно ли снабжать неким уникальным маркером каждый блок инфы, например: Код: plaintext 1. 2. 3. 4.
... |
|||
:
Нравится:
Не нравится:
|
|||
25.05.2012, 18:22 |
|
fbtracemgr: разные мелкие вопросы
|
|||
---|---|---|---|
#18+
Таблоид1) Что указывается в скобках ? Почему это число всё время одинаковое во всех блоках ?Идентификатор данной трейс-сессии в данном аттаче (или сервисе). Все сообщения с данным ид относятся к одному и тому же аттачу\сессии. Теоритически, может использоваться повторно Таблоид2) Можно ли снабжать неким уникальным маркером каждый блок инфыМожно, но это будет стоить немножко скорости в рантайме. Оно того не стоит, имхо. ... |
|||
:
Нравится:
Не нравится:
|
|||
25.05.2012, 21:35 |
|
fbtracemgr: разные мелкие вопросы
|
|||
---|---|---|---|
#18+
hvladэто будет стоить немножко скорости в рантайме. Оно того не стоит, имхо.но ведь так легче ссылаться на блоки, ибо они будут однозначно идентифицированы. Скорость в рантайме теряется и сейчас на "наладные расходы" вида отчеркивающих линий (80 знаков у "---...----" и 111 знаков у "***...***"). ... |
|||
:
Нравится:
Не нравится:
|
|||
25.05.2012, 23:36 |
|
fbtracemgr: разные мелкие вопросы
|
|||
---|---|---|---|
#18+
Таблоидно ведь так легче ссылаться на блоки, ибо они будут однозначно идентифицированы.Ничего не понял ТаблоидСкорость в рантайме теряется и сейчас на "наладные расходы" вида отчеркивающих линий (80 знаков у "---...----" и 111 знаков у "***...***").Лишь бы поспорить ? Ты мерял расходы на эти линии и на конкурентный межпроцессный счётчик ? ... |
|||
:
Нравится:
Не нравится:
|
|||
25.05.2012, 23:57 |
|
fbtracemgr: разные мелкие вопросы
|
|||
---|---|---|---|
#18+
hvladНичего не понялесть блоки, у которых проставлены совершенно одинаковые моменты времени в виду точности до 10 мс. Например, могут быть два одинаковых exe_trigger_finish'a с одинаковым временем (для db_level-триггера). Как их различить, когда идёт разбор полётов с коллегами (а я их устраиваю периодически :)) ? пальцем тыркать или копипастить в word и цветом выделять ? hvladТы мерял расходы на эти линии и на конкурентный межпроцессный счётчик ?Поясни, о какой конкуренции идёт речь ? лог трейса заполняется развене одним процессом, имя которому = fbtracemgr ? ... |
|||
:
Нравится:
Не нравится:
|
|||
26.05.2012, 00:17 |
|
fbtracemgr: разные мелкие вопросы
|
|||
---|---|---|---|
#18+
Таблоидесть блоки, у которых проставлены совершенно одинаковые моменты времени в виду точности до 10 мс. Например, могут быть два одинаковых exe_trigger_finish'a с одинаковым временем (для db_level-триггера). Как их различитьОни, вообще-то, друг за другом в файле лога идут. Можешь отличать по смещению или номеру строки, разрешаю Да и имена у двух db-level триггеров не могут совпадать... Таблоидлог трейса заполняется развене одним процессом, имя которому = fbtracemgr ?OMG fbtracemgr только читает лог используя сервисы А пишут его все процессы с движком внутри - как сервер, так и embedded ... |
|||
:
Нравится:
Не нравится:
|
|||
26.05.2012, 00:39 |
|
fbtracemgr: разные мелкие вопросы
|
|||
---|---|---|---|
#18+
hvladМожешь отличать по смещению или номеру строки, разрешаюгы... а какое "смещение или номер строки" можно указать при публикации фрагмента трейса тут, на форуме ? Или, допустим, я выслал своему коллеге часть трейса, начинающуюся НЕ с начала. Он тогда видит строки с совсем другими номерами, чем я. В общем - надо таки нумеровать блоки... :-) ... |
|||
:
Нравится:
Не нравится:
|
|||
26.05.2012, 00:45 |
|
fbtracemgr: разные мелкие вопросы
|
|||
---|---|---|---|
#18+
Таблоиддопустим, я выслал своему коллеге часть трейса, начинающуюся НЕ с начала Никогда не высылай обрывки логов. Чаще всего они бесполезны. Posted via ActualForum NNTP Server 1.5 ... |
|||
:
Нравится:
Не нравится:
|
|||
26.05.2012, 00:53 |
|
fbtracemgr: разные мелкие вопросы
|
|||
---|---|---|---|
#18+
ТаблоидВ общем - надо таки нумеровать блоки... :-)Нумеруй, я тут при чём ? Я не понимаю, к чему ты прицепился на этот раз ??? ... |
|||
:
Нравится:
Не нравится:
|
|||
26.05.2012, 01:04 |
|
fbtracemgr: разные мелкие вопросы
|
|||
---|---|---|---|
#18+
hvladНумеруй, я тут при чём ?чем нумеровать, шариковой ручкой что ли ? и что значит "я тут причем" ?! как будто кто-то еще в природе туда полезет. hvladЯ не понимаю, к чему ты прицепился на этот раз ???Очень прошу: введи опцию в fbtrace.conf, что-то типа: numerate_blocks, по дефолту = false. Кому надо, включат. ... |
|||
:
Нравится:
Не нравится:
|
|||
26.05.2012, 01:08 |
|
fbtracemgr: разные мелкие вопросы
|
|||
---|---|---|---|
#18+
Должен ли fbtracemgr, к которому я стучусь вот так: Код: plaintext
Код: plaintext 1. 2. 3.
Трейс по порту 3051: Код: plaintext 1. 2. 3. 4. 5. 6. 7. 8. 9. 10. 11. 12.
... |
|||
:
Нравится:
Не нравится:
|
|||
29.05.2012, 20:17 |
|
fbtracemgr: разные мелкие вопросы
|
|||
---|---|---|---|
#18+
Таблоид, должен ... |
|||
:
Нравится:
Не нравится:
|
|||
29.05.2012, 20:28 |
|
|
start [/forum/topic.php?fid=40&msg=37817094&tid=1561416]: |
0ms |
get settings: |
9ms |
get forum list: |
12ms |
check forum access: |
4ms |
check topic access: |
4ms |
track hit: |
153ms |
get topic data: |
9ms |
get forum data: |
2ms |
get page messages: |
56ms |
get tp. blocked users: |
1ms |
others: | 322ms |
total: | 572ms |
0 / 0 |