search

salsa-rs / salsa

A generic framework for on-demand, incrementalized computation. Inspired by adapton, glimmer, and rustc's query system.
https://salsa-rs.netlify.app/
Apache License 2.0
2.14k stars 152 forks source link

Noisy logging, excessive at INFO level #425

Open jblachly opened 1 year ago

jblachly commented 1 year ago

Problem Statement Salsa is verbosely logging query and computation events at the INFO level which makes it hard to find info from client libraries or applications in the logs.

Background and Motivation I am using citeproc-rs to render bibliographic citations into HTML; citeproc-rs uses salsa for computation of the citation style language (CSL).

I've written a service that accepts CSL and renders the citation to HTML and returns it. Below is an example of a single query for a single reference: (note that all but the first 3 lines originate in salsa)

2022-11-24T15:53:00.829653Z  INFO alexandria::style: FAST_STYLES is set; loading only 4 styles
2022-11-24T15:53:00.864827Z  INFO alexandria::style: Loaded 4 styles
2022-11-24T15:53:00.865803Z  INFO alexandria: Alexandria refmgr listening on 0.0.0.0:8048
2022-11-24T15:53:21.972674Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: GetBibliographyMapQuery(()): invoked at R17
2022-11-24T15:53:21.973018Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: GetBibliographyMapQuery(()): executing query
2022-11-24T15:53:21.973217Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: SortedRefsQuery(()): invoked at R17
2022-11-24T15:53:21.973384Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: SortedRefsQuery(()): executing query
2022-11-24T15:53:21.973539Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: CitedKeysQuery(()): invoked at R17
2022-11-24T15:53:21.973792Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: CitedKeysQuery(()): executing query
2022-11-24T15:53:21.973858Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: AllCiteIdsQuery(()): invoked at R17
2022-11-24T15:53:21.973902Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: AllCiteIdsQuery(()): executing query
2022-11-24T15:53:21.973933Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: ClustersSortedQuery(()): invoked at R17
2022-11-24T15:53:21.975951Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: ClustersSortedQuery(()): executing query
2022-11-24T15:53:21.976147Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: DisambParticipantsQuery(()): invoked at R17
2022-11-24T15:53:21.976192Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: DisambParticipantsQuery(()): executing query
2022-11-24T15:53:21.976214Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: CitedKeysQuery(()): invoked at R17
2022-11-24T15:53:21.976234Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: CitedKeysQuery(()): returning memoized value changed at R16
2022-11-24T15:53:21.976674Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: BibItemGen0Query(Atom('alexandria/pubmed/4599080' type=dynamic)): invoked at R17
2022-11-24T15:53:21.976804Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: BibItemGen0Query(Atom('alexandria/pubmed/4599080' type=dynamic)): executing query
2022-11-24T15:53:21.976858Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: SortedRefsQuery(()): invoked at R17
2022-11-24T15:53:21.976878Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: SortedRefsQuery(()): returning memoized value changed at R17
2022-11-24T15:53:21.976907Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: ReferenceQuery(Atom('alexandria/pubmed/4599080' type=dynamic)): invoked at R17
2022-11-24T15:53:21.976927Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: ReferenceQuery(Atom('alexandria/pubmed/4599080' type=dynamic)): executing query
2022-11-24T15:53:21.976982Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: DefaultLocaleQuery(()): invoked at R17
2022-11-24T15:53:21.977014Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: DefaultLocaleQuery(()): executing query
2022-11-24T15:53:21.977051Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: ParsedLocaleQuery(Inline(Some(Iso(English, Some(US))))): invoked at R17
2022-11-24T15:53:21.977073Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: ParsedLocaleQuery(Inline(Some(Iso(English, Some(US))))): executing query
2022-11-24T15:53:21.977104Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: ParsedLocaleQuery(Inline(Some(Iso(English, None)))): invoked at R17
2022-11-24T15:53:21.977121Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: ParsedLocaleQuery(Inline(Some(Iso(English, None)))): executing query
2022-11-24T15:53:21.977149Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: ParsedLocaleQuery(Inline(None)): invoked at R17
2022-11-24T15:53:21.977166Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: ParsedLocaleQuery(Inline(None)): executing query
2022-11-24T15:53:21.977194Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: ParsedLocaleQuery(File(Iso(English, Some(US)))): invoked at R17
2022-11-24T15:53:21.977212Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: ParsedLocaleQuery(File(Iso(English, Some(US)))): executing query
2022-11-24T15:53:21.983379Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: NameInfoBibliographyQuery(()): invoked at R17
2022-11-24T15:53:21.983436Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: NameInfoBibliographyQuery(()): executing query
2022-11-24T15:53:21.984405Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: DisambiguatedPersonNamesQuery(()): invoked at R17
2022-11-24T15:53:21.984439Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: DisambiguatedPersonNamesQuery(()): executing query
2022-11-24T15:53:21.984517Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: DisambiguatedPersonNamesQuery(()): invoked at R17
2022-11-24T15:53:21.984536Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: DisambiguatedPersonNamesQuery(()): returning memoized value changed at R12
2022-11-24T15:53:21.985416Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: YearSuffixForQuery(Atom('alexandria/pubmed/4599080' type=dynamic)): invoked at R17
2022-11-24T15:53:21.985468Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: YearSuffixForQuery(Atom('alexandria/pubmed/4599080' type=dynamic)): executing query
2022-11-24T15:53:21.985492Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: YearSuffixesQuery(()): invoked at R17
2022-11-24T15:53:21.985533Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: YearSuffixesQuery(()): executing query
2022-11-24T15:53:21.985579Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: AllCiteIdsQuery(()): invoked at R17
2022-11-24T15:53:21.985595Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: AllCiteIdsQuery(()): returning memoized value changed at R7
2022-11-24T15:53:21.985783Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: DefaultLocaleQuery(()): invoked at R17
2022-11-24T15:53:21.985802Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: DefaultLocaleQuery(()): returning memoized value changed at R13
2022-11-24T15:53:21.985960Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: SortedRefsQuery(()): invoked at R17
2022-11-24T15:53:21.985982Z  INFO render_csl{render_params=Query(RenderParams { style: "nature", locale: Some("en-US"), format: Some(Html) })}: salsa::derived::slot: SortedRefsQuery(()): returning memoized value changed at R17

Question Are you amenable to decreasing these messages to the TRACING or DEBUG level? If yes, is the current, non-2022 salsa accepting changes?

Thanks in advance

Geal commented 1 year ago

another data point here, we're using salsa at Apollo in the context of the apollo-rs graphql compiler tools, that is now going in our router, and these logs are very noisy. In general libraries tend to avoid logging at higher levels than debug or trace, and leave the rest to the main application.

I see that the src/derived/slot.rs file is not present on master, but there are still some info!() calls in recent files: https://github.com/salsa-rs/salsa/commit/356392578bb86d2aa287940bfe95ae6355f286a3#diff-f520734994fdb4b1ea8c2e1082b3676aa8f09e3af82d5e118fa5bf483b243be5R35